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/01/31 00:51:49 UTC
[JENKINS] Lucene-Solr-Tests-4.x-java7 - Build # 949 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-java7/949/
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([99977DE9BBE172F2]: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([99977DE9BBE172F2]:0)
Build Log:
[...truncated 9360 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 0 T797 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_/p
[junit4:junit4] 2> 4 T797 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1359582669545
[junit4:junit4] 2> 5 T797 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 6 T798 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 9 T798 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 9 T798 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T798 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 10 T798 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 11 T798 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T797 oasc.ZkTestServer.run start zk server on port:35586
[junit4:junit4] 2> 106 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@b61bc93
[junit4:junit4] 2> 107 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T803 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 108 T803 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 109 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:27330
[junit4:junit4] 2> 110 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:27330
[junit4:junit4] 2> 110 T801 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 124 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00000 with negotiated timeout 10000 for client /140.211.11.196:27330
[junit4:junit4] 2> 124 T803 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00000, negotiated timeout = 10000
[junit4:junit4] 2> 124 T804 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b61bc93 name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 125 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 125 T797 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 130 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00000
[junit4:junit4] 2> 131 T804 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 131 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00000 closed
[junit4:junit4] 2> 132 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:27330 which had sessionid 0x13c8d712af00000
[junit4:junit4] 2> 132 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3f6c0a70
[junit4:junit4] 2> 133 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 133 T805 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 133 T805 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 133 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:49304
[junit4:junit4] 2> 134 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:49304
[junit4:junit4] 2> 135 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00001 with negotiated timeout 10000 for client /140.211.11.196:49304
[junit4:junit4] 2> 135 T805 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00001, negotiated timeout = 10000
[junit4:junit4] 2> 135 T806 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f6c0a70 name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 135 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 136 T797 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 146 T797 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 149 T797 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 152 T797 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 159 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 160 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 173 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 174 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 290 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 290 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 294 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 294 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 305 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 305 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 308 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 309 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 319 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 320 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 323 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 324 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 330 T797 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 331 T797 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 338 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00001
[junit4:junit4] 2> 345 T806 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 345 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00001 closed
[junit4:junit4] 2> 345 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:49304 which had sessionid 0x13c8d712af00001
[junit4:junit4] 2> 467 T797 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 471 T797 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:51040
[junit4:junit4] 2> 471 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 471 T797 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 472 T797 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886
[junit4:junit4] 2> 472 T797 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/solr.xml
[junit4:junit4] 2> 472 T797 oasc.CoreContainer.<init> New CoreContainer 1235249833
[junit4:junit4] 2> 473 T797 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/'
[junit4:junit4] 2> 473 T797 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/'
[junit4:junit4] 2> 516 T797 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 517 T797 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 517 T797 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 517 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 518 T797 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 518 T797 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 518 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 518 T797 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 519 T797 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 519 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 535 T797 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 549 T797 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35586/solr
[junit4:junit4] 2> 550 T797 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 550 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1da91778
[junit4:junit4] 2> 551 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 551 T816 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 552 T816 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 552 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:39991
[junit4:junit4] 2> 553 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:39991
[junit4:junit4] 2> 565 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00002 with negotiated timeout 20000 for client /140.211.11.196:39991
[junit4:junit4] 2> 565 T816 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00002, negotiated timeout = 20000
[junit4:junit4] 2> 565 T817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1da91778 name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 565 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 567 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00002
[junit4:junit4] 2> 574 T817 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 574 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:39991 which had sessionid 0x13c8d712af00002
[junit4:junit4] 2> 574 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00002 closed
[junit4:junit4] 2> 574 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 584 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ce9e911
[junit4:junit4] 2> 585 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 585 T818 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 585 T818 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 586 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:19499
[junit4:junit4] 2> 586 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:19499
[junit4:junit4] 2> 587 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00003 with negotiated timeout 20000 for client /140.211.11.196:19499
[junit4:junit4] 2> 587 T818 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00003, negotiated timeout = 20000
[junit4:junit4] 2> 587 T819 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ce9e911 name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 588 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 590 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 598 T797 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 600 T797 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51040__%2Fp
[junit4:junit4] 2> 601 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51040__%2Fp Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51040__%2Fp
[junit4:junit4] 2> 602 T797 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51040__%2Fp
[junit4:junit4] 2> 612 T797 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 623 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:delete cxid:0x15 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 624 T797 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 633 T797 oasc.Overseer.start Overseer (id=89101609831759875-127.0.0.1:51040__%2Fp-n_0000000000) starting
[junit4:junit4] 2> 633 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 634 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 641 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 642 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 649 T821 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 650 T797 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 659 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 661 T820 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 665 T822 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/collection1
[junit4:junit4] 2> 665 T822 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 666 T822 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 666 T822 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 668 T822 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/collection1/'
[junit4:junit4] 2> 668 T822 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 669 T822 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/collection1/lib/README' to classloader
[junit4:junit4] 2> 706 T822 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 754 T822 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 855 T822 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 860 T822 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1329 T822 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1337 T822 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1340 T822 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1354 T822 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1358 T822 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1361 T822 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1362 T822 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1363 T822 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1359582669886/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/
[junit4:junit4] 2> 1363 T822 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@65bd831f
[junit4:junit4] 2> 1364 T822 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1364 T822 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data forceNew:false
[junit4:junit4] 2> 1365 T822 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data
[junit4:junit4] 2> 1365 T822 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index/
[junit4:junit4] 2> 1365 T822 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1366 T822 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index forceNew:false
[junit4:junit4] 2> 1370 T822 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b5791c1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1371 T822 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1371 T822 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index
[junit4:junit4] 2> 1371 T822 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 1373 T822 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1373 T822 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 1373 T822 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1374 T822 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 1374 T822 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1374 T822 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1374 T822 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1375 T822 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1375 T822 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1376 T822 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 1376 T822 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 1376 T822 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1377 T822 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 1377 T822 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 1377 T822 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 1377 T822 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1378 T822 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1378 T822 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1378 T822 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1379 T822 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1379 T822 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1379 T822 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1380 T822 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1380 T822 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1380 T822 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 1381 T822 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 1389 T822 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1392 T822 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 1393 T822 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 1395 T822 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data
[junit4:junit4] 2> 1396 T822 oass.SolrIndexSearcher.<init> Opening Searcher@514e39d main
[junit4:junit4] 2> 1397 T822 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1397 T822 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1397 T822 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 1412 T822 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 1453 T823 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@514e39d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1457 T822 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1457 T822 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1458 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 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> 2166 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2167 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:51040__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51040/_/p"}
[junit4:junit4] 2> 2167 T820 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2167 T820 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2168 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 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> 2192 T819 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> 2471 T822 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2471 T822 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51040/_/p collection:control_collection shard:shard1
[junit4:junit4] 2> 2472 T822 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2489 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 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> 2490 T822 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2490 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2493 T822 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2493 T822 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2493 T822 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51040/_/p/collection1/
[junit4:junit4] 2> 2493 T822 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2493 T822 oasc.SyncStrategy.syncToMe http://127.0.0.1:51040/_/p/collection1/ has no replicas
[junit4:junit4] 2> 2494 T822 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51040/_/p/collection1/
[junit4:junit4] 2> 2494 T822 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2499 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3698 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3715 T819 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> 3776 T822 oasc.ZkController.register We are http://127.0.0.1:51040/_/p/collection1/ and leader is http://127.0.0.1:51040/_/p/collection1/
[junit4:junit4] 2> 3776 T822 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51040/_/p
[junit4:junit4] 2> 3776 T822 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3776 T822 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3776 T822 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3779 T822 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3780 T797 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3781 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3782 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3797 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3807 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@db5e278
[junit4:junit4] 2> 3808 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3808 T824 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3809 T824 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 3809 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:34052
[junit4:junit4] 2> 3809 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:34052
[junit4:junit4] 2> 3811 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00004 with negotiated timeout 10000 for client /140.211.11.196:34052
[junit4:junit4] 2> 3811 T824 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00004, negotiated timeout = 10000
[junit4:junit4] 2> 3812 T825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@db5e278 name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3812 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3813 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3816 T797 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3999 T797 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4002 T797 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:36434
[junit4:junit4] 2> 4003 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4003 T797 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4004 T797 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356
[junit4:junit4] 2> 4004 T797 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/solr.xml
[junit4:junit4] 2> 4005 T797 oasc.CoreContainer.<init> New CoreContainer 1610023527
[junit4:junit4] 2> 4006 T797 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/'
[junit4:junit4] 2> 4006 T797 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/'
[junit4:junit4] 2> 4066 T797 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 4067 T797 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4067 T797 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4068 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4068 T797 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4069 T797 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4069 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4070 T797 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4070 T797 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4071 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4092 T797 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4112 T797 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35586/solr
[junit4:junit4] 2> 4113 T797 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4113 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@75246eeb
[junit4:junit4] 2> 4114 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4115 T835 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4115 T835 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 4116 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63463
[junit4:junit4] 2> 4116 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63463
[junit4:junit4] 2> 4118 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00005 with negotiated timeout 20000 for client /140.211.11.196:63463
[junit4:junit4] 2> 4118 T835 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00005, negotiated timeout = 20000
[junit4:junit4] 2> 4119 T836 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@75246eeb name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4119 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4120 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00005
[junit4:junit4] 2> 4150 T836 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4150 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63463 which had sessionid 0x13c8d712af00005
[junit4:junit4] 2> 4150 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00005 closed
[junit4:junit4] 2> 4151 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 4162 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@622b212c
[junit4:junit4] 2> 4163 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4163 T837 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4164 T837 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 4164 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:52295
[junit4:junit4] 2> 4164 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:52295
[junit4:junit4] 2> 4188 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00006 with negotiated timeout 20000 for client /140.211.11.196:52295
[junit4:junit4] 2> 4188 T837 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00006, negotiated timeout = 20000
[junit4:junit4] 2> 4189 T838 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@622b212c name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4189 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4190 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4204 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4247 T797 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36434__%2Fp
[junit4:junit4] 2> 4248 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:36434__%2Fp Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:36434__%2Fp
[junit4:junit4] 2> 4283 T797 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36434__%2Fp
[junit4:junit4] 2> 4292 T819 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> 4293 T825 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4302 T819 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4303 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4311 T839 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/collection1
[junit4:junit4] 2> 4312 T839 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4312 T839 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4313 T839 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4314 T839 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/collection1/'
[junit4:junit4] 2> 4315 T839 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4316 T839 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/collection1/lib/README' to classloader
[junit4:junit4] 2> 4370 T839 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 4442 T839 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4543 T839 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4550 T839 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5172 T839 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5180 T839 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5183 T839 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5199 T839 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5203 T839 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5207 T839 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5208 T839 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5209 T839 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1359582673356/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/
[junit4:junit4] 2> 5210 T839 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@65bd831f
[junit4:junit4] 2> 5210 T839 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 5211 T839 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1 forceNew:false
[junit4:junit4] 2> 5211 T839 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> 5211 T839 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index/
[junit4:junit4] 2> 5212 T839 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5213 T839 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index forceNew:false
[junit4:junit4] 2> 5218 T839 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@277d1913),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5218 T839 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5218 T839 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index
[junit4:junit4] 2> 5219 T839 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 5220 T839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5220 T839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 5221 T839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5221 T839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 5221 T839 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5222 T839 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5222 T839 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5222 T839 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5223 T839 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5223 T839 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 5224 T839 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 5224 T839 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5224 T839 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 5224 T839 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 5225 T839 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 5225 T839 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5226 T839 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5226 T839 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5226 T839 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5227 T839 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5227 T839 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5228 T839 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5228 T839 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5229 T839 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5229 T839 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 5229 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5229 T839 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 5230 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:51040__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51040/_/p"}
[junit4:junit4] 2> 5240 T839 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5242 T819 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> 5242 T838 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> 5242 T825 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> 5244 T839 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 5246 T839 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 5248 T839 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> 5249 T839 oass.SolrIndexSearcher.<init> Opening Searcher@504c5413 main
[junit4:junit4] 2> 5250 T839 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5250 T839 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5251 T839 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 5256 T839 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 5307 T840 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@504c5413 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5312 T839 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5312 T839 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6747 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6748 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:36434__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36434/_/p"}
[junit4:junit4] 2> 6748 T820 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 6749 T820 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6788 T819 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> 6788 T825 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> 6788 T838 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> 7315 T839 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7315 T839 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36434/_/p collection:collection1 shard:shard1
[junit4:junit4] 2> 7316 T839 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7335 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:delete cxid:0x45 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7336 T839 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7336 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:create cxid:0x46 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7339 T839 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7339 T839 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7339 T839 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36434/_/p/collection1/
[junit4:junit4] 2> 7339 T839 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7340 T839 oasc.SyncStrategy.syncToMe http://127.0.0.1:36434/_/p/collection1/ has no replicas
[junit4:junit4] 2> 7340 T839 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36434/_/p/collection1/
[junit4:junit4] 2> 7340 T839 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7345 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00006 type:create cxid:0x50 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8294 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8312 T825 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> 8312 T819 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> 8312 T838 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> 8316 T839 oasc.ZkController.register We are http://127.0.0.1:36434/_/p/collection1/ and leader is http://127.0.0.1:36434/_/p/collection1/
[junit4:junit4] 2> 8316 T839 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36434/_/p
[junit4:junit4] 2> 8316 T839 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8316 T839 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8317 T839 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8323 T839 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8334 T797 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8335 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8335 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8521 T797 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8524 T797 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:11991
[junit4:junit4] 2> 8525 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8525 T797 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8526 T797 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891
[junit4:junit4] 2> 8526 T797 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/solr.xml
[junit4:junit4] 2> 8527 T797 oasc.CoreContainer.<init> New CoreContainer 1344885481
[junit4:junit4] 2> 8528 T797 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/'
[junit4:junit4] 2> 8528 T797 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/'
[junit4:junit4] 2> 8584 T797 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 8584 T797 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8585 T797 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8585 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8586 T797 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8586 T797 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8587 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8587 T797 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8587 T797 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8588 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8609 T797 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8628 T797 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35586/solr
[junit4:junit4] 2> 8629 T797 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8629 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@6ec5a493
[junit4:junit4] 2> 8630 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8631 T850 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8632 T850 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 8632 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:60079
[junit4:junit4] 2> 8632 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:60079
[junit4:junit4] 2> 8634 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00007 with negotiated timeout 20000 for client /140.211.11.196:60079
[junit4:junit4] 2> 8635 T850 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00007, negotiated timeout = 20000
[junit4:junit4] 2> 8635 T851 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ec5a493 name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8635 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8637 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00007
[junit4:junit4] 2> 8643 T851 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8643 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:60079 which had sessionid 0x13c8d712af00007
[junit4:junit4] 2> 8643 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00007 closed
[junit4:junit4] 2> 8644 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 8661 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4fdcda8c
[junit4:junit4] 2> 8663 T852 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8663 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8663 T852 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 8664 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:29896
[junit4:junit4] 2> 8664 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:29896
[junit4:junit4] 2> 8665 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00008 with negotiated timeout 20000 for client /140.211.11.196:29896
[junit4:junit4] 2> 8665 T852 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00008, negotiated timeout = 20000
[junit4:junit4] 2> 8666 T853 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4fdcda8c name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8666 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8667 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8669 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8671 T797 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:11991__%2Fp
[junit4:junit4] 2> 8672 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:delete cxid:0x4 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:11991__%2Fp Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:11991__%2Fp
[junit4:junit4] 2> 8679 T797 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:11991__%2Fp
[junit4:junit4] 2> 8682 T825 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> 8682 T838 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> 8682 T819 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> 8684 T825 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8684 T838 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8685 T819 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8688 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 8695 T854 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/collection1
[junit4:junit4] 2> 8695 T854 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 8696 T854 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 8696 T854 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 8698 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/collection1/'
[junit4:junit4] 2> 8699 T854 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/collection1/lib/README' to classloader
[junit4:junit4] 2> 8699 T854 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 8753 T854 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 8834 T854 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 8935 T854 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 8946 T854 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9690 T854 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9699 T854 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9702 T854 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9718 T854 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9723 T854 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9727 T854 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9729 T854 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9730 T854 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1359582677891/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/
[junit4:junit4] 2> 9731 T854 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@65bd831f
[junit4:junit4] 2> 9731 T854 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 9732 T854 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2 forceNew:false
[junit4:junit4] 2> 9732 T854 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 9732 T854 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index/
[junit4:junit4] 2> 9733 T854 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9734 T854 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index forceNew:false
[junit4:junit4] 2> 9738 T854 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4994e6e0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9738 T854 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9739 T854 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index
[junit4:junit4] 2> 9739 T854 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 9741 T854 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9741 T854 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 9741 T854 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9742 T854 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 9742 T854 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9742 T854 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9743 T854 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9743 T854 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9743 T854 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9744 T854 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 9744 T854 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 9745 T854 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9745 T854 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 9745 T854 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 9745 T854 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 9746 T854 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9746 T854 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9747 T854 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9747 T854 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9747 T854 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9748 T854 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9748 T854 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9749 T854 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9749 T854 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9750 T854 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 9750 T854 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 9760 T854 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9764 T854 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 9765 T854 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 9767 T854 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 9769 T854 oass.SolrIndexSearcher.<init> Opening Searcher@1ab7b508 main
[junit4:junit4] 2> 9769 T854 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9770 T854 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9770 T854 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 9776 T854 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 9824 T855 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ab7b508 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9828 T854 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9828 T854 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9836 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9837 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:36434__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36434/_/p"}
[junit4:junit4] 2> 9841 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:11991__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:11991/_/p"}
[junit4:junit4] 2> 9841 T820 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 9841 T820 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 9853 T825 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> 9853 T819 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> 9853 T838 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> 9853 T853 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> 10830 T854 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 10830 T854 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:11991/_/p collection:collection1 shard:shard2
[junit4:junit4] 2> 10831 T854 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 10839 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:delete cxid:0x42 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4] 2> 10848 T854 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 10848 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:create cxid:0x43 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10851 T854 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 10852 T854 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 10852 T854 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:11991/_/p/collection1/
[junit4:junit4] 2> 10852 T854 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 10852 T854 oasc.SyncStrategy.syncToMe http://127.0.0.1:11991/_/p/collection1/ has no replicas
[junit4:junit4] 2> 10852 T854 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:11991/_/p/collection1/
[junit4:junit4] 2> 10853 T854 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 10862 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af00008 type:create cxid:0x4c zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11367 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11385 T819 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> 11385 T825 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> 11385 T838 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> 11385 T853 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> 11426 T854 oasc.ZkController.register We are http://127.0.0.1:11991/_/p/collection1/ and leader is http://127.0.0.1:11991/_/p/collection1/
[junit4:junit4] 2> 11426 T854 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:11991/_/p
[junit4:junit4] 2> 11426 T854 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 11426 T854 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 11426 T854 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11429 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11430 T797 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11431 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11431 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11616 T797 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11620 T797 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:17669
[junit4:junit4] 2> 11620 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11621 T797 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11621 T797 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986
[junit4:junit4] 2> 11622 T797 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/solr.xml
[junit4:junit4] 2> 11622 T797 oasc.CoreContainer.<init> New CoreContainer 1207366573
[junit4:junit4] 2> 11623 T797 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/'
[junit4:junit4] 2> 11623 T797 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/'
[junit4:junit4] 2> 11679 T797 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 11680 T797 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11680 T797 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11681 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11681 T797 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11682 T797 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11682 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11683 T797 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11683 T797 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11683 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11704 T797 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11724 T797 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35586/solr
[junit4:junit4] 2> 11724 T797 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11725 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5a1eee41
[junit4:junit4] 2> 11726 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11726 T865 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 11727 T865 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 11727 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:28592
[junit4:junit4] 2> 11728 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:28592
[junit4:junit4] 2> 11730 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af00009 with negotiated timeout 20000 for client /140.211.11.196:28592
[junit4:junit4] 2> 11730 T865 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af00009, negotiated timeout = 20000
[junit4:junit4] 2> 11730 T866 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a1eee41 name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11730 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11732 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af00009
[junit4:junit4] 2> 11745 T866 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11745 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:28592 which had sessionid 0x13c8d712af00009
[junit4:junit4] 2> 11745 T797 oaz.ZooKeeper.close Session: 0x13c8d712af00009 closed
[junit4:junit4] 2> 11746 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 11756 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4456d453
[junit4:junit4] 2> 11757 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11758 T867 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 11758 T867 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 11758 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:48051
[junit4:junit4] 2> 11759 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:48051
[junit4:junit4] 2> 11760 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af0000a with negotiated timeout 20000 for client /140.211.11.196:48051
[junit4:junit4] 2> 11760 T867 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af0000a, negotiated timeout = 20000
[junit4:junit4] 2> 11760 T868 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4456d453 name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11761 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11762 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11764 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000a type:create cxid:0x2 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11765 T797 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:17669__%2Fp
[junit4:junit4] 2> 11766 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000a type:delete cxid:0x4 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:17669__%2Fp Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:17669__%2Fp
[junit4:junit4] 2> 11774 T797 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:17669__%2Fp
[junit4:junit4] 2> 11777 T825 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> 11777 T853 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> 11777 T838 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> 11777 T819 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> 11780 T825 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11780 T838 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11780 T853 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11780 T819 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11783 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 11790 T869 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/collection1
[junit4:junit4] 2> 11790 T869 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 11791 T869 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 11791 T869 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 11793 T869 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/collection1/'
[junit4:junit4] 2> 11794 T869 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/collection1/lib/README' to classloader
[junit4:junit4] 2> 11795 T869 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 11848 T869 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 11918 T869 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 12019 T869 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 12025 T869 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 12633 T869 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 12641 T869 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 12644 T869 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 12658 T869 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 12662 T869 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 12665 T869 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 12666 T869 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 12668 T869 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1359582680986/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/
[junit4:junit4] 2> 12668 T869 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@65bd831f
[junit4:junit4] 2> 12668 T869 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 12669 T869 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3 forceNew:false
[junit4:junit4] 2> 12669 T869 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 12669 T869 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index/
[junit4:junit4] 2> 12670 T869 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 12671 T869 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index forceNew:false
[junit4:junit4] 2> 12675 T869 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@72fe0d35),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12675 T869 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12675 T869 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index
[junit4:junit4] 2> 12676 T869 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 12677 T869 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 12677 T869 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 12678 T869 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 12678 T869 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 12678 T869 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 12679 T869 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 12679 T869 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 12679 T869 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 12680 T869 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 12680 T869 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 12681 T869 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 12681 T869 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 12681 T869 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 12681 T869 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 12682 T869 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 12682 T869 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 12683 T869 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12683 T869 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12683 T869 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12684 T869 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12684 T869 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12685 T869 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12685 T869 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12685 T869 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12686 T869 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 12686 T869 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 12695 T869 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 12698 T869 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 12699 T869 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 12700 T869 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 12702 T869 oass.SolrIndexSearcher.<init> Opening Searcher@10337e8e main
[junit4:junit4] 2> 12702 T869 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 12703 T869 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 12703 T869 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 12718 T869 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 12759 T870 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10337e8e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 12763 T869 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 12763 T869 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12900 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12900 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:11991__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:11991/_/p"}
[junit4:junit4] 2> 12905 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:17669__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17669/_/p"}
[junit4:junit4] 2> 12905 T820 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 12905 T820 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 12916 T825 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> 12916 T819 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> 12916 T868 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> 12917 T838 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> 12916 T853 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> 13765 T869 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 13765 T869 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:17669/_/p collection:collection1 shard:shard1
[junit4:junit4] 2> 13770 T869 oasc.ZkController.register We are http://127.0.0.1:17669/_/p/collection1/ and leader is http://127.0.0.1:36434/_/p/collection1/
[junit4:junit4] 2> 13770 T869 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:17669/_/p
[junit4:junit4] 2> 13770 T869 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 13770 T869 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C52 name=collection1 org.apache.solr.core.SolrCore@718a5a00 url=http://127.0.0.1:17669/_/p/collection1 node=127.0.0.1:17669__%2Fp C52_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:17669__%2Fp, base_url=http://127.0.0.1:17669/_/p}
[junit4:junit4] 2> 13771 T871 C52 P17669 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 13771 T869 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13772 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 13772 T871 C52 P17669 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 13772 T871 C52 P17669 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 13773 T797 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 13774 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 13774 T871 C52 P17669 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13774 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13975 T797 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 13978 T797 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64830
[junit4:junit4] 2> 13979 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 13979 T797 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 13980 T797 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332
[junit4:junit4] 2> 13980 T797 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/solr.xml
[junit4:junit4] 2> 13981 T797 oasc.CoreContainer.<init> New CoreContainer 2137580609
[junit4:junit4] 2> 13982 T797 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/'
[junit4:junit4] 2> 13982 T797 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/'
[junit4:junit4] 2> 14047 T797 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 14048 T797 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 14048 T797 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 14049 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 14049 T797 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 14050 T797 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 14050 T797 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 14050 T797 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 14051 T797 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 14051 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 14074 T797 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 14095 T797 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35586/solr
[junit4:junit4] 2> 14096 T797 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 14097 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@48e2c096
[junit4:junit4] 2> 14098 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14098 T881 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 14099 T881 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 14099 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:32225
[junit4:junit4] 2> 14100 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:32225
[junit4:junit4] 2> 14103 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af0000b with negotiated timeout 20000 for client /140.211.11.196:32225
[junit4:junit4] 2> 14103 T881 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af0000b, negotiated timeout = 20000
[junit4:junit4] 2> 14103 T882 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48e2c096 name:ZooKeeperConnection Watcher:127.0.0.1:35586 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14103 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14105 T802 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c8d712af0000b
[junit4:junit4] 2> 14148 T882 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 14148 T799 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:32225 which had sessionid 0x13c8d712af0000b
[junit4:junit4] 2> 14148 T797 oaz.ZooKeeper.close Session: 0x13c8d712af0000b closed
[junit4:junit4] 2> 14149 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 14160 T797 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35586/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@efd2f0b
[junit4:junit4] 2> 14161 T797 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14161 T883 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:35586. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 14162 T883 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:35586, initiating session
[junit4:junit4] 2> 14162 T799 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:62930
[junit4:junit4] 2> 14162 T799 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:62930
[junit4:junit4] 2> 14164 T801 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c8d712af0000c with negotiated timeout 20000 for client /140.211.11.196:62930
[junit4:junit4] 2> 14164 T883 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:35586, sessionid = 0x13c8d712af0000c, negotiated timeout = 20000
[junit4:junit4] 2> 14164 T884 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@efd2f0b name:ZooKeeperConnection Watcher:127.0.0.1:35586/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14164 T797 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14166 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000c type:create cxid:0x1 zxid:0xa0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 14189 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000c type:create cxid:0x2 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 14191 T797 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64830__%2Fp
[junit4:junit4] 2> 14192 T802 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c8d712af0000c type:delete cxid:0x4 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64830__%2Fp Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64830__%2Fp
[junit4:junit4] 2> 14193 T797 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64830__%2Fp
[junit4:junit4] 2> 14195 T825 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> 14196 T838 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> 14196 T853 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> 14196 T819 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> 14196 T868 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14197 T868 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> 14198 T838 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14198 T853 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14199 T825 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14200 T819 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14201 T797 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 14209 T885 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/collection1
[junit4:junit4] 2> 14209 T885 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 14210 T885 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 14210 T885 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 14212 T885 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/collection1/'
[junit4:junit4] 2> 14213 T885 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 14213 T885 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/collection1/lib/README' to classloader
[junit4:junit4] 2> 14268 T885 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 14340 T885 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 14430 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14431 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:17669__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17669/_/p"}
[junit4:junit4] 2> 14441 T885 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 14448 T885 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 14451 T825 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> 14451 T853 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> 14451 T884 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> 14451 T838 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> 14451 T819 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> 14451 T868 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> 14942 T885 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 14950 T885 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 14953 T885 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 14967 T885 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14971 T885 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14974 T885 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14975 T885 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14977 T885 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1359582683332/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/
[junit4:junit4] 2> 14977 T885 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@65bd831f
[junit4:junit4] 2> 14977 T885 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 14978 T885 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4 forceNew:false
[junit4:junit4] 2> 14978 T885 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 14978 T885 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index/
[junit4:junit4] 2> 14979 T885 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 14980 T885 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index forceNew:false
[junit4:junit4] 2> 14984 T885 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@732f85fb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14985 T885 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14985 T885 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index
[junit4:junit4] 2> 14985 T885 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 14987 T885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 14987 T885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 14987 T885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 14988 T885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 14988 T885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 14988 T885 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 14989 T885 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 14989 T885 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 14990 T885 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 14990 T885 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 14990 T885 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 14991 T885 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 14991 T885 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 14991 T885 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 14992 T885 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 14992 T885 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 14992 T885 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14993 T885 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14993 T885 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14994 T885 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14994 T885 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14994 T885 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14995 T885 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14995 T885 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 14996 T885 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 14996 T885 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 15004 T885 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 15007 T885 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 15008 T885 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 15010 T885 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 15011 T885 oass.SolrIndexSearcher.<init> Opening Searcher@51f4c07 main
[junit4:junit4] 2> 15012 T885 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 15012 T885 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 15013 T885 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 15029 T885 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 15073 T886 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51f4c07 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 15077 T885 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15078 T885 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15958 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15959 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:64830__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64830/_/p"}
[junit4:junit4] 2> 15959 T820 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 15960 T820 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 15975 T825 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> 15975 T819 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> 15975 T838 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> 15975 T884 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> 15975 T868 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> 15975 T853 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> 16080 T885 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16080 T885 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64830/_/p collection:collection1 shard:shard2
[junit4:junit4] 2> 16085 T885 oasc.ZkController.register We are http://127.0.0.1:64830/_/p/collection1/ and leader is http://127.0.0.1:11991/_/p/collection1/
[junit4:junit4] 2> 16085 T885 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64830/_/p
[junit4:junit4] 2> 16086 T885 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16086 T885 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C53 name=collection1 org.apache.solr.core.SolrCore@b067134 url=http://127.0.0.1:64830/_/p/collection1 node=127.0.0.1:64830__%2Fp C53_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64830__%2Fp, base_url=http://127.0.0.1:64830/_/p}
[junit4:junit4] 2> 16086 T887 C53 P64830 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16087 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16087 T885 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16087 T887 C53 P64830 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16088 T887 C53 P64830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16088 T797 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 16089 T797 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16089 T887 C53 P64830 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16090 T797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16112 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16114 T797 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 16115 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C52_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:17669__%2Fp, base_url=http://127.0.0.1:17669/_/p}
[junit4:junit4] 2> 16796 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36434/_/p/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 16796 T871 C52 P17669 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:17669/_/p START replicas=[http://127.0.0.1:36434/_/p/collection1/] nUpdates=100
[junit4:junit4] 2> 16797 T871 C52 P17669 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 16798 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 16798 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 16798 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 16798 T871 C52 P17669 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 16798 T871 C52 P17669 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36434/_/p/collection1/. core=collection1
[junit4:junit4] 2> 16799 T871 C52 P17669 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C54 name=collection1 org.apache.solr.core.SolrCore@5680ae91 url=http://127.0.0.1:36434/_/p/collection1 node=127.0.0.1:36434__%2Fp C54_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:36434__%2Fp, base_url=http://127.0.0.1:36434/_/p, leader=true}
[junit4:junit4] 2> 16816 T829 C54 P36434 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 16818 T830 C54 P36434 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 16819 T830 C54 P36434 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> 16824 T830 C54 P36434 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@277d1913),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 16824 T830 C54 P36434 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 16828 T830 C54 P36434 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@277d1913),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@277d1913),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 16828 T830 C54 P36434 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 16829 T830 C54 P36434 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> 16830 T830 C54 P36434 oass.SolrIndexSearcher.<init> Opening Searcher@1985ab11 realtime
[junit4:junit4] 2> 16830 T830 C54 P36434 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 16831 T830 C54 P36434 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 16832 T871 C52 P17669 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16832 T871 C52 P17669 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 16834 T831 C54 P36434 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16835 T831 C54 P36434 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 16836 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 16836 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 16836 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 16838 T831 C54 P36434 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> 16839 T831 C54 P36434 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1/index
[junit4:junit4] 2> 16839 T831 C54 P36434 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 16840 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 16842 T871 C52 P17669 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 forceNew:false
[junit4:junit4] 2> 16842 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16843 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 lockFactory=org.apache.lucene.store.NativeFSLockFactory@532bcdef) fullCopy=true
[junit4:junit4] 2> 16846 T831 C54 P36434 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 16848 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index
[junit4:junit4] 2> 16848 T871 C52 P17669 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 16849 T871 C52 P17669 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130131035126381
[junit4:junit4] 2> 16850 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16851 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16851 T871 C52 P17669 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381
[junit4:junit4] 2> 16855 T871 C52 P17669 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 lockFactory=org.apache.lucene.store.NativeFSLockFactory@532bcdef),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 16855 T871 C52 P17669 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 16857 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16857 T871 C52 P17669 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 16857 T871 C52 P17669 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 16857 T871 C52 P17669 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 16858 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381
[junit4:junit4] 2> 16859 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16862 T871 C52 P17669 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 lockFactory=org.apache.lucene.store.NativeFSLockFactory@532bcdef),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 16863 T871 C52 P17669 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 16863 T871 C52 P17669 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 16863 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16864 T871 C52 P17669 oass.SolrIndexSearcher.<init> Opening Searcher@1f82ffc7 main
[junit4:junit4] 2> 16866 T870 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f82ffc7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 16866 T870 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index
[junit4:junit4] 2> 16867 T871 C52 P17669 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 16869 T871 C52 P17669 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 lockFactory=org.apache.lucene.store.NativeFSLockFactory@532bcdef),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381 lockFactory=org.apache.lucene.store.NativeFSLockFactory@532bcdef),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 16869 T871 C52 P17669 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 16870 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 16871 T871 C52 P17669 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 16871 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index.20130131035126381
[junit4:junit4] 2> 16871 T871 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3/index
[junit4:junit4] 2> 16871 T871 C52 P17669 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 16871 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 16871 T871 C52 P17669 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 16872 T871 C52 P17669 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16879 T871 C52 P17669 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 17118 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17482 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17483 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:64830__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64830/_/p"}
[junit4:junit4] 2> 17488 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:17669__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17669/_/p"}
[junit4:junit4] 2> 17500 T825 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> 17500 T819 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> 17500 T838 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> 17500 T868 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> 17500 T884 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> 17500 T853 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> 18120 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19123 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C53_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64830__%2Fp, base_url=http://127.0.0.1:64830/_/p}
[junit4:junit4] 2> 20116 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:11991/_/p/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 20116 T887 C53 P64830 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64830/_/p START replicas=[http://127.0.0.1:11991/_/p/collection1/] nUpdates=100
[junit4:junit4] 2> 20117 T887 C53 P64830 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 20117 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 20117 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 20117 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 20117 T887 C53 P64830 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 20117 T887 C53 P64830 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:11991/_/p/collection1/. core=collection1
[junit4:junit4] 2> 20118 T887 C53 P64830 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 20126 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C55 name=collection1 org.apache.solr.core.SolrCore@18b444ea url=http://127.0.0.1:11991/_/p/collection1 node=127.0.0.1:11991__%2Fp C55_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:11991__%2Fp, base_url=http://127.0.0.1:11991/_/p, leader=true}
[junit4:junit4] 2> 20134 T844 C55 P11991 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 20141 T845 C55 P11991 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 20142 T845 C55 P11991 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 20146 T845 C55 P11991 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4994e6e0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 20147 T845 C55 P11991 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 20150 T845 C55 P11991 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4994e6e0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4994e6e0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20151 T845 C55 P11991 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20152 T845 C55 P11991 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 20152 T845 C55 P11991 oass.SolrIndexSearcher.<init> Opening Searcher@74367338 realtime
[junit4:junit4] 2> 20153 T845 C55 P11991 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20153 T845 C55 P11991 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 20154 T887 C53 P64830 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 20154 T887 C53 P64830 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 20156 T846 C55 P11991 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 20157 T846 C55 P11991 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 20157 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 20157 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 20158 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 20160 T846 C55 P11991 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 20161 T846 C55 P11991 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2/index
[junit4:junit4] 2> 20161 T846 C55 P11991 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 20162 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 20163 T887 C53 P64830 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 forceNew:false
[junit4:junit4] 2> 20164 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20164 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1569d624) fullCopy=true
[junit4:junit4] 2> 20168 T846 C55 P11991 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 20170 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index
[junit4:junit4] 2> 20170 T887 C53 P64830 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 20170 T887 C53 P64830 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130131035129703
[junit4:junit4] 2> 20172 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20172 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20172 T887 C53 P64830 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703
[junit4:junit4] 2> 20176 T887 C53 P64830 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1569d624),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20176 T887 C53 P64830 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20178 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20178 T887 C53 P64830 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 20178 T887 C53 P64830 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 20178 T887 C53 P64830 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 20179 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703
[junit4:junit4] 2> 20180 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20183 T887 C53 P64830 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1569d624),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20183 T887 C53 P64830 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20184 T887 C53 P64830 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 20184 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20184 T887 C53 P64830 oass.SolrIndexSearcher.<init> Opening Searcher@201f0542 main
[junit4:junit4] 2> 20186 T886 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@201f0542 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 20187 T886 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index
[junit4:junit4] 2> 20187 T887 C53 P64830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 20189 T887 C53 P64830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1569d624),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1569d624),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 20190 T887 C53 P64830 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 20191 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 20191 T887 C53 P64830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20191 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index.20130131035129703
[junit4:junit4] 2> 20191 T887 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4/index
[junit4:junit4] 2> 20191 T887 C53 P64830 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 20192 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 20192 T887 C53 P64830 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 20192 T887 C53 P64830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 20200 T887 C53 P64830 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20517 T820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20518 T820 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[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:64830__%2Fp",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64830/_/p"}
[junit4:junit4] 2> 20531 T825 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> 20531 T853 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> 20531 T838 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> 20531 T819 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> 20531 T868 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> 20531 T884 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> 21129 T797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21130 T797 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C56 name=collection1 org.apache.solr.core.SolrCore@2a9a4933 url=http://127.0.0.1:51040/_/p/collection1 node=127.0.0.1:51040__%2Fp C56_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51040__%2Fp, base_url=http://127.0.0.1:51040/_/p, leader=true}
[junit4:junit4] 2> 21143 T809 C56 P51040 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data
[junit4:junit4] 2> 21148 T809 C56 P51040 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b5791c1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 21148 T809 C56 P51040 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 21150 T809 C56 P51040 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/control/data
[junit4:junit4] 2> 21151 T809 C56 P51040 oass.SolrIndexSearcher.<init> Opening Searcher@4fb79c90 realtime
[junit4:junit4] 2> 21152 T809 C56 P51040 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1425625779464568832)} 0 10
[junit4:junit4] 2> 21156 T847 C55 P11991 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty2
[junit4:junit4] 2> 21160 T832 C54 P36434 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty1
[junit4:junit4] 2> C53_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64830__%2Fp, base_url=http://127.0.0.1:64830/_/p}
[junit4:junit4] 2> 21171 T874 C53 P64830 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty4
[junit4:junit4] 2> 21172 T874 C53 P64830 /update {update.distrib=FROMLEADER&_version_=-1425625779477151744&update.from=http://127.0.0.1:11991/_/p/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1425625779477151744)} 0 4
[junit4:junit4] 2> C52_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:17669__%2Fp, base_url=http://127.0.0.1:17669/_/p}
[junit4:junit4] 2> 21175 T858 C52 P17669 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1359582669544/jetty3
[junit4:junit4] 2> 21176 T858 C52 P17669 /update {update.distrib=FROMLEADER&_version_=-1425625779482394624&update.from=http://127.0.0.1:36434/_/p/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1425625779482394624)} 0 3
[junit4:junit4] 2> 21177 T832 C54 P36434 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1425625779482394624)} 0 18
[junit4:junit4] 2> 21178 T847 C55 P11991 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1425625779477151744)} 0 24
[junit4:junit4] 2> 21186 T809 C56 P51040 /update {wt=javabin&version=2} {add=[1 (1425625779506511872)]} 0 5
[junit4:junit4] 2> 21201 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1425625779513851904)]} 0 5
[junit4:junit4] 2> 21201 T833 C54 P36434 /update {wt=javabin&version=2} {add=[1 (1425625779513851904)]} 0 13
[junit4:junit4] 2> 21207 T809 C56 P51040 /update {wt=javabin&version=2} {add=[2 (1425625779531677696)]} 0 2
[junit4:junit4] 2> 21224 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1425625779537969152)]} 0 5
[junit4:junit4] 2> 21224 T848 C55 P11991 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1425625779537969152)]} 0 12
[junit4:junit4] 2> 21225 T833 C54 P36434 /update {wt=javabin&version=2} {add=[2]} 0 15
[junit4:junit4] 2> 21230 T809 C56 P51040 /update {wt=javabin&version=2} {add=[3 (1425625779555794944)]} 0 2
[junit4:junit4] 2> 21242 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1425625779563134976)]} 0 2
[junit4:junit4] 2> 21243 T848 C55 P11991 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1425625779563134976)]} 0 7
[junit4:junit4] 2> 21244 T833 C54 P36434 /update {wt=javabin&version=2} {add=[3]} 0 11
[junit4:junit4] 2> 21249 T809 C56 P51040 /update {wt=javabin&version=2} {add=[4 (1425625779575717888)]} 0 2
[junit4:junit4] 2> 21262 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1425625779584106496)]} 0 2
[junit4:junit4] 2> 21263 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1425625779584106496)]} 0 8
[junit4:junit4] 2> 21264 T847 C55 P11991 /update {wt=javabin&version=2} {add=[4]} 0 12
[junit4:junit4] 2> 21269 T809 C56 P51040 /update {wt=javabin&version=2} {add=[5 (1425625779595640832)]} 0 2
[junit4:junit4] 2> 21279 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1425625779601932288)]} 0 2
[junit4:junit4] 2> 21280 T847 C55 P11991 /update {wt=javabin&version=2} {add=[5 (1425625779601932288)]} 0 8
[junit4:junit4] 2> 21285 T809 C56 P51040 /update {wt=javabin&version=2} {add=[6 (1425625779612418048)]} 0 2
[junit4:junit4] 2> 21294 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1425625779618709504)]} 0 2
[junit4:junit4] 2> 21295 T847 C55 P11991 /update {wt=javabin&version=2} {add=[6 (1425625779618709504)]} 0 7
[junit4:junit4] 2> 21300 T809 C56 P51040 /update {wt=javabin&version=2} {add=[7 (1425625779629195264)]} 0 2
[junit4:junit4] 2> 21309 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1425625779634438144)]} 0 2
[junit4:junit4] 2> 21310 T847 C55 P11991 /update {wt=javabin&version=2} {add=[7 (1425625779634438144)]} 0 7
[junit4:junit4] 2> 21315 T809 C56 P51040 /update {wt=javabin&version=2} {add=[8 (1425625779644923904)]} 0 2
[junit4:junit4] 2> 21329 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1425625779653312512)]} 0 3
[junit4:junit4] 2> 21330 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1425625779653312512)]} 0 9
[junit4:junit4] 2> 21331 T847 C55 P11991 /update {wt=javabin&version=2} {add=[8]} 0 13
[junit4:junit4] 2> 21336 T809 C56 P51040 /update {wt=javabin&version=2} {add=[9 (1425625779666944000)]} 0 2
[junit4:junit4] 2> 21349 T874 C53 P64830 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1425625779675332608)]} 0 2
[junit4:junit4] 2> 21350 T848 C55 P11991 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1425625779675332608)]} 0 8
[junit4:junit4] 2> 21351 T833 C54 P36434 /update {wt=javabin&version=2} {add=[9]} 0 12
[junit4:junit4] 2> 21389 T809 C56 P51040 /update {wt=javabin&version=2} {add=[10 (1425625779687915520)]} 0 35
[junit4:junit4] 2> 21399 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1425625779727761408)]} 0 2
[junit4:junit4] 2> 21400 T833 C54 P36434 /update {wt=javabin&version=2} {add=[10 (1425625779727761408)]} 0 8
[junit4:junit4] 2> 21407 T809 C56 P51040 /update {wt=javabin&version=2} {add=[11 (1425625779739295744)]} 0 4
[junit4:junit4] 2> 21417 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1425625779746635776)]} 0 2
[junit4:junit4] 2> 21418 T833 C54 P36434 /update {wt=javabin&version=2} {add=[11 (1425625779746635776)]} 0 8
[junit4:junit4] 2> 21423 T809 C56 P51040 /update {wt=javabin&version=2} {add=[12 (1425625779758170112)]} 0 2
[junit4:junit4] 2> 21436 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1425625779765510144)]} 0 2
[junit4:junit4] 2> 21437 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1425625779765510144)]} 0 8
[junit4:junit4] 2> 21438 T847 C55 P11991 /update {wt=javabin&version=2} {add=[12]} 0 12
[junit4:junit4] 2> 21443 T809 C56 P51040 /update {wt=javabin&version=2} {add=[13 (1425625779779141632)]} 0 2
[junit4:junit4] 2> 21457 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1425625779787530240)]} 0 3
[junit4:junit4] 2> 21458 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1425625779787530240)]} 0 9
[junit4:junit4] 2> 21459 T847 C55 P11991 /update {wt=javabin&version=2} {add=[13]} 0 13
[junit4:junit4] 2> 21464 T809 C56 P51040 /update {wt=javabin&version=2} {add=[14 (1425625779801161728)]} 0 2
[junit4:junit4] 2> 21476 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1425625779808501760)]} 0 2
[junit4:junit4] 2> 21476 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1425625779808501760)]} 0 6
[junit4:junit4] 2> 21477 T847 C55 P11991 /update {wt=javabin&version=2} {add=[14]} 0 10
[junit4:junit4] 2> 21482 T809 C56 P51040 /update {wt=javabin&version=2} {add=[15 (1425625779820036096)]} 0 2
[junit4:junit4] 2> 21494 T858 C52 P17669 /update {distrib.from=http://127.0.0.1:36434/_/p/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1425625779827376128)]} 0 2
[junit4:junit4] 2> 21494 T832 C54 P36434 /update {distrib.from=http://127.0.0.1:11991/_/p/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (142
[...truncated too long message...]
nt.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 38) Thread[id=855, name=searcherExecutor-382-thread-1, state=WAITING, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4:junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
[junit4:junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
[junit4:junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 39) Thread[id=873, name=qtp126943190-873 Acceptor0 SocketConnector@127.0.0.1:64830, 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> 40) Thread[id=827, name=qtp1471637831-827 Acceptor0 SocketConnector@127.0.0.1:36434, 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> 41) Thread[id=883, name=TEST-BasicDistributedZkTest.testDistribSearch-seed#[99977DE9BBE172F2]-SendThread(localhost:35586), state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:82)
[junit4:junit4] 2> at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:338)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1068)
[junit4:junit4] 2> 42) Thread[id=996, name=searcherExecutor-468-thread-1, state=WAITING, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4:junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
[junit4:junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
[junit4:junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 43) Thread[id=840, name=searcherExecutor-372-thread-1, state=WAITING, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4:junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
[junit4:junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
[junit4:junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41: {n_f1=PostingsFormat(name=Asserting), foo_b=PostingsFormat(name=MockSep), foo_d=MockFixedIntBlock(blockSize=1180), foo_f=PostingsFormat(name=MockSep), n_tl1=PostingsFormat(name=Asserting), n_d1=PostingsFormat(name=SimpleText), rnd_b=MockFixedIntBlock(blockSize=1180), intDefault=PostingsFormat(name=Asserting), n_td1=PostingsFormat(name=Asserting), timestamp=PostingsFormat(name=Asserting), id=MockFixedIntBlock(blockSize=1180), range_facet_sl=MockFixedIntBlock(blockSize=1180), range_facet_si=PostingsFormat(name=SimpleText), oddField_s=MockFixedIntBlock(blockSize=1180), multiDefault=PostingsFormat(name=Asserting), n_tf1=PostingsFormat(name=SimpleText), n_dt1=PostingsFormat(name=Asserting), n_ti1=MockFixedIntBlock(blockSize=1180), range_facet_l=PostingsFormat(name=Asserting), text=PostingsFormat(name=MockSep), _version_=PostingsFormat(name=Asserting), SubjectTerms_mfacet=PostingsFormat(name=Asserting), a_t=PostingsFormat(name=SimpleText), n_tdt1=PostingsFormat(name=Asserting), other_tl1=PostingsFormat(name=Asserting), n_l1=PostingsFormat(name=SimpleText), a_si=PostingsFormat(name=Asserting)}, sim=DefaultSimilarity, locale=sq, timezone=Asia/Dhaka
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_09 (64-bit)/cpus=16,threads=48,free=226453616,total=287309824
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DefaultValueUpdateProcessorTest, TestQuerySenderNoQuery, TestLMDirichletSimilarityFactory, ChaosMonkeyNothingIsSafeTest, TestElisionMultitermQuery, TestIndexSearcher, JSONWriterTest, DateFieldTest, LoggingHandlerTest, SpellPossibilityIteratorTest, DistributedSpellCheckComponentTest, TestFiltering, SimplePostToolTest, MBeansHandlerTest, DateMathParserTest, TestBinaryResponseWriter, IndexBasedSpellCheckerTest, ScriptEngineTest, MoreLikeThisHandlerTest, ShardRoutingTest, DistributedTermsComponentTest, TestSolrQueryParser, TestPartialUpdateDeduplication, TestRangeQuery, SolrCmdDistributorTest, WordBreakSolrSpellCheckerTest, SuggesterFSTTest, SolrRequestParserTest, FileBasedSpellCheckerTest, SolrPluginUtilsTest, TestWordDelimiterFilterFactory, TestDefaultSimilarityFactory, UniqFieldsUpdateProcessorFactoryTest, TestPerFieldSimilarity, TestFastLRUCache, TestStressRecovery, TestQueryTypes, BasicDistributedZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZkTest -Dtests.seed=99977DE9BBE172F2 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sq -Dtests.timezone=Asia/Dhaka -Dtests.file.encoding=US-ASCII
[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([99977DE9BBE172F2]:0)
[junit4:junit4] Completed on J0 in 7223.99s, 1 test, 2 errors <<< FAILURES!
[...truncated 77 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:346: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build.xml:178: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/common-build.xml:428: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:1176: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:841: There were test failures: 248 suites, 1035 tests, 1 suite-level error, 1 error, 89 ignored (5 assumptions)
Total time: 143 minutes 49 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure