You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2014/01/08 03:12:50 UTC

[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.8.0-ea-b121) - Build # 3651 - Failure!

Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/3651/
Java: 64bit/jdk1.8.0-ea-b121 -XX:+UseCompressedOops -XX:+UseG1GC

2 tests failed.
FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.MigrateRouteKeyTest

Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.MigrateRouteKeyTest:     1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]         at java.lang.Object.wait(Native Method)         at java.lang.Object.wait(Object.java:502)         at java.util.TimerThread.mainLoop(Timer.java:526)         at java.util.TimerThread.run(Timer.java:505)

Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.MigrateRouteKeyTest: 
   1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.util.TimerThread.mainLoop(Timer.java:526)
        at java.util.TimerThread.run(Timer.java:505)
	at __randomizedtesting.SeedInfo.seed([ACB193B066BABF80]:0)


FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.MigrateRouteKeyTest

Error Message:
There are still zombie threads that couldn't be terminated:    1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]         at java.lang.Object.wait(Native Method)         at java.lang.Object.wait(Object.java:502)         at java.util.TimerThread.mainLoop(Timer.java:526)         at java.util.TimerThread.run(Timer.java:505)

Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
   1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.util.TimerThread.mainLoop(Timer.java:526)
        at java.util.TimerThread.run(Timer.java:505)
	at __randomizedtesting.SeedInfo.seed([ACB193B066BABF80]:0)




Build Log:
[...truncated 10451 lines...]
   [junit4] Suite: org.apache.solr.cloud.MigrateRouteKeyTest
   [junit4]   2> 1120217 T5399 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
   [junit4]   2> 1120223 T5399 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
   [junit4]   2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-MigrateRouteKeyTest-1389147000673
   [junit4]   2> 1120227 T5399 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 1120229 T5400 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 1120329 T5399 oasc.ZkTestServer.run start zk server on port:52999
   [junit4]   2> 1120330 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1120345 T5406 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2af688bb name:ZooKeeperConnection Watcher:127.0.0.1:52999 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1120346 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1120346 T5399 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 1120354 T5401 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1436f9d0f720000, likely client has closed socket
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:744)
   [junit4]   2> 
   [junit4]   2> 1120357 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1120363 T5408 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@779ac301 name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1120363 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1120363 T5399 oascc.SolrZkClient.makePath makePath: /collections/collection1
   [junit4]   2> 1120368 T5399 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
   [junit4]   2> 1120374 T5399 oascc.SolrZkClient.makePath makePath: /collections/control_collection
   [junit4]   2> 1120378 T5399 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
   [junit4]   2> 1120384 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
   [junit4]   2> 1120386 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
   [junit4]   2> 1120396 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
   [junit4]   2> 1120397 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
   [junit4]   2> 1120403 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 1120404 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 1120411 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
   [junit4]   2> 1120411 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
   [junit4]   2> 1120418 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
   [junit4]   2> 1120418 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
   [junit4]   2> 1120424 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
   [junit4]   2> 1120424 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
   [junit4]   2> 1120431 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\enumsConfig.xml to /configs/conf1/enumsConfig.xml
   [junit4]   2> 1120431 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
   [junit4]   2> 1120438 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
   [junit4]   2> 1120439 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
   [junit4]   2> 1120445 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 1120446 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 1120451 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
   [junit4]   2> 1120452 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
   [junit4]   2> 1120456 T5399 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
   [junit4]   2> 1120457 T5399 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
   [junit4]   2> 1120465 T5401 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1436f9d0f720001, likely client has closed socket
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:744)
   [junit4]   2> 
   [junit4]   2> 1121097 T5399 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1121106 T5399 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53006
   [junit4]   2> 1121107 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1121107 T5399 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1121107 T5399 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912
   [junit4]   2> 1121107 T5399 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\'
   [junit4]   2> 1121147 T5399 oasc.ConfigSolr.fromFile Loading container configuration from C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\solr.xml
   [junit4]   2> 1121159 T5399 oasc.CoreContainer.<init> New CoreContainer 1959377560
   [junit4]   2> 1121162 T5399 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\]
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1121162 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1121164 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1121164 T5399 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1121164 T5399 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1121172 T5399 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1121172 T5399 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1121172 T5399 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 1121172 T5399 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52999/solr
   [junit4]   2> 1121172 T5399 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1121175 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1121191 T5419 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7586ffb2 name:ZooKeeperConnection Watcher:127.0.0.1:52999 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1121192 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1121198 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1121204 T5421 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f2826ca name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1121205 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1121209 T5399 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 1121216 T5399 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 1121224 T5399 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 1121229 T5399 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53006_
   [junit4]   2> 1121232 T5399 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53006_
   [junit4]   2> 1121240 T5399 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 1121247 T5399 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 1121257 T5399 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 1121262 T5399 oasc.Overseer.start Overseer (id=91039137837219843-127.0.0.1:53006_-n_0000000000) starting
   [junit4]   2> 1121269 T5399 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 1121277 T5423 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 1121278 T5399 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 1121283 T5399 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 1121287 T5399 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1121292 T5422 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 1121298 T5424 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1121298 T5424 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1121301 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1121301 T5424 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1121304 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1121306 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53006",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53006_",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 1121306 T5422 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
   [junit4]   2> 1121306 T5422 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 1121311 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1121315 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1122292 T5424 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1122292 T5424 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\collection1
   [junit4]   2> 1122293 T5424 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
   [junit4]   2> 1122294 T5424 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1122294 T5424 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 1122297 T5424 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\collection1\'
   [junit4]   2> 1122300 T5424 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912/collection1/lib/classes/' to classloader
   [junit4]   2> 1122302 T5424 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912/collection1/lib/README' to classloader
   [junit4]   2> 1122346 T5424 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1122361 T5424 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1122365 T5424 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1122372 T5424 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1122531 T5424 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1122532 T5424 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1122533 T5424 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1122538 T5424 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1122576 T5424 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1122576 T5424 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ..\..\..\..\..\..\..\..\..\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-controljetty-1389147000912\collection1\, dataDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/control/data\
   [junit4]   2> 1122577 T5424 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2b1c58cc
   [junit4]   2> 1122577 T5424 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/control/data\
   [junit4]   2> 1122578 T5424 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/control/data\index/
   [junit4]   2> 1122578 T5424 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670\control\data\index' doesn't exist. Creating new index...
   [junit4]   2> 1122578 T5424 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/control/data\index
   [junit4]   2> 1122579 T5424 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=15, maxMergeAtOnceExplicit=49, maxMergedSegmentMB=82.6357421875, floorSegmentMB=1.2548828125, forceMergeDeletesPctAllowed=28.67659816569696, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8753618963937313
   [junit4]   2> 1122580 T5424 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@702913b9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@58b33458),segFN=segments_1,generation=1}
   [junit4]   2> 1122580 T5424 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1122586 T5424 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 1122587 T5424 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 1122588 T5424 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1122588 T5424 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1122588 T5424 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1122589 T5424 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 1122589 T5424 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1122589 T5424 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1122589 T5424 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1122590 T5424 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1122591 T5424 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1122591 T5424 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1122592 T5424 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1122592 T5424 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1122593 T5424 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1122594 T5424 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 1122594 T5424 oasc.RequestHandlers.initHandlersFromConfig created /admin/fileedit: solr.admin.EditFileRequestHandler
   [junit4]   2> 1122604 T5424 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1122613 T5424 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1122614 T5424 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1122615 T5424 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=26.814453125, floorSegmentMB=1.2529296875, forceMergeDeletesPctAllowed=7.506434250323016, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 1122615 T5424 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@702913b9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@58b33458),segFN=segments_1,generation=1}
   [junit4]   2> 1122616 T5424 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1122616 T5424 oass.SolrIndexSearcher.<init> Opening Searcher@561acf38 main
   [junit4]   2> 1122618 T5425 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@561acf38 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1122621 T5424 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1122622 T5399 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
   [junit4]   2> 1122623 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1122622 T5428 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53006 collection:control_collection shard:shard1
   [junit4]   2> 1122625 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1122626 T5428 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
   [junit4]   2> 1122630 T5430 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e0d085b name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1122630 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1122632 T5399 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1122638 T5399 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
   [junit4]   2> 1122644 T5428 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 1122647 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122649 T5428 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1122649 T5428 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C903 name=collection1 org.apache.solr.core.SolrCore@3917c1b1 url=http://127.0.0.1:53006/collection1 node=127.0.0.1:53006_ C903_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:53006, core=collection1, node_name=127.0.0.1:53006_}
   [junit4]   2> 1122649 T5428 C903 P53006 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53006/collection1/
   [junit4]   2> 1122649 T5428 C903 P53006 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1122649 T5428 C903 P53006 oasc.SyncStrategy.syncToMe http://127.0.0.1:53006/collection1/ has no replicas
   [junit4]   2> 1122651 T5428 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53006/collection1/ shard1
   [junit4]   2> 1122651 T5428 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
   [junit4]   2> 1122654 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1122662 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122667 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122674 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122786 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1122787 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1122820 T5428 oasc.ZkController.register We are http://127.0.0.1:53006/collection1/ and leader is http://127.0.0.1:53006/collection1/
   [junit4]   2> 1122820 T5428 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53006
   [junit4]   2> 1122820 T5428 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1122820 T5428 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1122820 T5428 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1122823 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122823 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122823 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122825 T5428 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1122828 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1122829 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53006",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53006_",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 1122835 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1122939 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1122939 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1123415 T5399 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1123421 T5399 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53018
   [junit4]   2> 1123421 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1123421 T5399 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1123423 T5399 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086
   [junit4]   2> 1123423 T5399 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\'
   [junit4]   2> 1123459 T5399 oasc.ConfigSolr.fromFile Loading container configuration from C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\solr.xml
   [junit4]   2> 1123472 T5399 oasc.CoreContainer.<init> New CoreContainer 1819076523
   [junit4]   2> 1123472 T5399 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\]
   [junit4]   2> 1123473 T5399 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 1123473 T5399 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1123473 T5399 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1123473 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1123474 T5399 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1123474 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1123474 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1123474 T5399 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1123474 T5399 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1123479 T5399 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1123479 T5399 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1123479 T5399 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 1123479 T5399 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52999/solr
   [junit4]   2> 1123479 T5399 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1123482 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1123488 T5441 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30541b71 name:ZooKeeperConnection Watcher:127.0.0.1:52999 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1123488 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1123495 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1123498 T5443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@483011fe name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1123499 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1123506 T5399 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1124501 T5399 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53018_
   [junit4]   2> 1124503 T5399 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53018_
   [junit4]   2> 1124508 T5430 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1124509 T5443 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1124509 T5421 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1124519 T5444 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1124520 T5444 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1124522 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1124522 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1124522 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1124522 T5444 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1124524 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1124525 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53018",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53018_",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 1124525 T5422 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2]
   [junit4]   2> 1124525 T5422 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 1124531 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1124533 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1124533 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1124534 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1125512 T5444 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1125512 T5444 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\collection1
   [junit4]   2> 1125512 T5444 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1125515 T5444 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1125515 T5444 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1125517 T5444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\collection1\'
   [junit4]   2> 1125520 T5444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086/collection1/lib/classes/' to classloader
   [junit4]   2> 1125521 T5444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086/collection1/lib/README' to classloader
   [junit4]   2> 1125555 T5444 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1125563 T5444 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1125565 T5444 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1125571 T5444 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1125682 T5444 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1125684 T5444 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1125685 T5444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1125689 T5444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1125727 T5444 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1125729 T5444 oasc.SolrCore.<init> [collection1] Opening new SolrCore at .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty1-1389147003086\collection1\, dataDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty1\
   [junit4]   2> 1125729 T5444 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2b1c58cc
   [junit4]   2> 1125730 T5444 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty1\
   [junit4]   2> 1125730 T5444 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty1\index/
   [junit4]   2> 1125730 T5444 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670\jetty1\index' doesn't exist. Creating new index...
   [junit4]   2> 1125731 T5444 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty1\index
   [junit4]   2> 1125731 T5444 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=15, maxMergeAtOnceExplicit=49, maxMergedSegmentMB=82.6357421875, floorSegmentMB=1.2548828125, forceMergeDeletesPctAllowed=28.67659816569696, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8753618963937313
   [junit4]   2> 1125732 T5444 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f6f20bb lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@de61399),segFN=segments_1,generation=1}
   [junit4]   2> 1125732 T5444 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1125735 T5444 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 1125736 T5444 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 1125736 T5444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1125737 T5444 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1125737 T5444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1125737 T5444 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 1125738 T5444 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1125738 T5444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1125738 T5444 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1125739 T5444 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1125739 T5444 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1125740 T5444 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1125740 T5444 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1125741 T5444 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1125741 T5444 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1125742 T5444 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 1125743 T5444 oasc.RequestHandlers.initHandlersFromConfig created /admin/fileedit: solr.admin.EditFileRequestHandler
   [junit4]   2> 1125752 T5444 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1125759 T5444 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1125759 T5444 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1125761 T5444 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=26.814453125, floorSegmentMB=1.2529296875, forceMergeDeletesPctAllowed=7.506434250323016, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 1125762 T5444 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f6f20bb lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@de61399),segFN=segments_1,generation=1}
   [junit4]   2> 1125762 T5444 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1125762 T5444 oass.SolrIndexSearcher.<init> Opening Searcher@1f3b6144 main
   [junit4]   2> 1125766 T5444 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1125766 T5445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f3b6144 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1125767 T5399 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
   [junit4]   2> 1125767 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1125771 T5448 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53018 collection:collection1 shard:shard2
   [junit4]   2> 1125774 T5448 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 1125805 T5448 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
   [junit4]   2> 1125826 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1125828 T5448 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1125828 T5448 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C904 name=collection1 org.apache.solr.core.SolrCore@1c060cdf url=http://127.0.0.1:53018/collection1 node=127.0.0.1:53018_ C904_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:53018, core=collection1, node_name=127.0.0.1:53018_}
   [junit4]   2> 1125828 T5448 C904 P53018 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53018/collection1/
   [junit4]   2> 1125829 T5448 C904 P53018 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1125829 T5448 C904 P53018 oasc.SyncStrategy.syncToMe http://127.0.0.1:53018/collection1/ has no replicas
   [junit4]   2> 1125830 T5448 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53018/collection1/ shard2
   [junit4]   2> 1125830 T5448 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 1125833 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1125851 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1125857 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1125866 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1125972 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1125974 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1125975 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1126010 T5448 oasc.ZkController.register We are http://127.0.0.1:53018/collection1/ and leader is http://127.0.0.1:53018/collection1/
   [junit4]   2> 1126011 T5448 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53018
   [junit4]   2> 1126011 T5448 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1126011 T5448 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1126011 T5448 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1126014 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1126014 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1126015 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1126016 T5448 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1126019 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1126020 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53018",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53018_",
   [junit4]   2> 	  "shard":"shard2",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 1126026 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1126131 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1126132 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1126132 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1126473 T5399 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1126478 T5399 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53027
   [junit4]   2> 1126478 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1126478 T5399 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1126478 T5399 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214
   [junit4]   2> 1126480 T5399 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\'
   [junit4]   2> 1126517 T5399 oasc.ConfigSolr.fromFile Loading container configuration from C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\solr.xml
   [junit4]   2> 1126530 T5399 oasc.CoreContainer.<init> New CoreContainer 1491344040
   [junit4]   2> 1126530 T5399 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\]
   [junit4]   2> 1126534 T5399 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1126535 T5399 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1126543 T5399 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1126543 T5399 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1126547 T5399 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 1126547 T5399 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52999/solr
   [junit4]   2> 1126547 T5399 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1126551 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1126558 T5459 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d524b1d name:ZooKeeperConnection Watcher:127.0.0.1:52999 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1126559 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1126564 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1126568 T5461 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@455c03ac name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1126570 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1126576 T5399 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1127573 T5399 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53027_
   [junit4]   2> 1127576 T5399 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53027_
   [junit4]   2> 1127581 T5421 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1127582 T5430 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1127582 T5461 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1127582 T5443 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1127596 T5462 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1127596 T5462 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1127600 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1127600 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1127600 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1127600 T5462 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1127607 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1127608 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53027",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53027_",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 1127609 T5422 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
   [junit4]   2> 1127609 T5422 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 1127614 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1127720 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1127720 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1127720 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1127720 T5461 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1128590 T5462 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1128590 T5462 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\collection1
   [junit4]   2> 1128590 T5462 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1128592 T5462 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1128592 T5462 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1128595 T5462 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\collection1\'
   [junit4]   2> 1128598 T5462 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214/collection1/lib/classes/' to classloader
   [junit4]   2> 1128600 T5462 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214/collection1/lib/README' to classloader
   [junit4]   2> 1128650 T5462 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1128665 T5462 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1128673 T5462 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1128681 T5462 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1128827 T5462 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1128829 T5462 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1128830 T5462 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1128835 T5462 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1128868 T5462 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1128868 T5462 oasc.SolrCore.<init> [collection1] Opening new SolrCore at .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty2-1389147006214\collection1\, dataDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty2\
   [junit4]   2> 1128868 T5462 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2b1c58cc
   [junit4]   2> 1128869 T5462 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty2\
   [junit4]   2> 1128869 T5462 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty2\index/
   [junit4]   2> 1128870 T5462 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670\jetty2\index' doesn't exist. Creating new index...
   [junit4]   2> 1128870 T5462 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty2\index
   [junit4]   2> 1128870 T5462 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=15, maxMergeAtOnceExplicit=49, maxMergedSegmentMB=82.6357421875, floorSegmentMB=1.2548828125, forceMergeDeletesPctAllowed=28.67659816569696, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8753618963937313
   [junit4]   2> 1128871 T5462 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6aecf05e lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@78c15c54),segFN=segments_1,generation=1}
   [junit4]   2> 1128871 T5462 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1128875 T5462 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 1128875 T5462 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 1128875 T5462 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1128875 T5462 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1128876 T5462 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1128876 T5462 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 1128877 T5462 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1128877 T5462 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1128877 T5462 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1128878 T5462 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1128878 T5462 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1128879 T5462 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1128879 T5462 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1128879 T5462 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1128881 T5462 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1128881 T5462 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 1128881 T5462 oasc.RequestHandlers.initHandlersFromConfig created /admin/fileedit: solr.admin.EditFileRequestHandler
   [junit4]   2> 1128886 T5462 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1128889 T5462 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1128889 T5462 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1128890 T5462 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=26.814453125, floorSegmentMB=1.2529296875, forceMergeDeletesPctAllowed=7.506434250323016, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 1128890 T5462 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6aecf05e lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@78c15c54),segFN=segments_1,generation=1}
   [junit4]   2> 1128891 T5462 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1128891 T5462 oass.SolrIndexSearcher.<init> Opening Searcher@13433907 main
   [junit4]   2> 1128895 T5463 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13433907 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1128896 T5462 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1128897 T5399 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
   [junit4]   2> 1128898 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1128898 T5466 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53027 collection:collection1 shard:shard1
   [junit4]   2> 1128901 T5466 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 1128911 T5466 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 1128915 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1128915 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1128915 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1128916 T5466 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1128916 T5466 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C905 name=collection1 org.apache.solr.core.SolrCore@52b3b2b6 url=http://127.0.0.1:53027/collection1 node=127.0.0.1:53027_ C905_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:53027, core=collection1, node_name=127.0.0.1:53027_}
   [junit4]   2> 1128916 T5466 C905 P53027 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53027/collection1/
   [junit4]   2> 1128916 T5466 C905 P53027 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1128916 T5466 C905 P53027 oasc.SyncStrategy.syncToMe http://127.0.0.1:53027/collection1/ has no replicas
   [junit4]   2> 1128916 T5466 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53027/collection1/ shard1
   [junit4]   2> 1128916 T5466 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 1128919 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1128924 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1128928 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1128933 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1129027 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129028 T5461 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129028 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129028 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129065 T5466 oasc.ZkController.register We are http://127.0.0.1:53027/collection1/ and leader is http://127.0.0.1:53027/collection1/
   [junit4]   2> 1129065 T5466 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53027
   [junit4]   2> 1129065 T5466 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1129065 T5466 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1129065 T5466 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1129069 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1129069 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1129069 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1129072 T5466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1129075 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1129075 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53027",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53027_",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":"core_node2"}
   [junit4]   2> 1129082 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1129175 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129176 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129177 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129176 T5461 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1129442 T5399 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1129445 T5399 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53036
   [junit4]   2> 1129445 T5399 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1129445 T5399 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1129445 T5399 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346
   [junit4]   2> 1129445 T5399 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\'
   [junit4]   2> 1129476 T5399 oasc.ConfigSolr.fromFile Loading container configuration from C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\solr.xml
   [junit4]   2> 1129488 T5399 oasc.CoreContainer.<init> New CoreContainer 866193448
   [junit4]   2> 1129488 T5399 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\]
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1129489 T5399 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1129493 T5399 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1129493 T5399 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1129493 T5399 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 1129493 T5399 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52999/solr
   [junit4]   2> 1129493 T5399 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1129497 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1129506 T5477 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4db2670e name:ZooKeeperConnection Watcher:127.0.0.1:52999 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1129507 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1129509 T5401 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1436f9d0f720009, likely client has closed socket
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
   [junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
   [junit4]   2> 	at java.lang.Thread.run(Thread.java:744)
   [junit4]   2> 
   [junit4]   2> 1129510 T5399 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1129517 T5479 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7e79855b name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1129517 T5399 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1129525 T5399 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1130421 T5399 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53036_
   [junit4]   2> 1130424 T5399 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53036_
   [junit4]   2> 1130428 T5421 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1130429 T5461 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1130430 T5443 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1130430 T5479 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1130430 T5430 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1130438 T5480 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1130438 T5480 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1130439 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1130439 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1130440 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1130439 T5480 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1130442 T5422 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1130445 T5422 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:53036",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:53036_",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "shard_parent":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 1130446 T5422 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
   [junit4]   2> 1130447 T5422 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 1130454 T5421 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 1130545 T5443 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1130546 T5461 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1130546 T5479 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1130547 T5421 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1130547 T5430 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1131333 T5480 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1131333 T5480 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\collection1
   [junit4]   2> 1131333 T5480 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1131334 T5480 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1131334 T5480 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1131336 T5480 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '.\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\collection1\'
   [junit4]   2> 1131338 T5480 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346/collection1/lib/classes/' to classloader
   [junit4]   2> 1131338 T5480 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346/collection1/lib/README' to classloader
   [junit4]   2> 1131372 T5480 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1131380 T5480 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1131382 T5480 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1131387 T5480 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1131510 T5480 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1131512 T5480 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1131513 T5480 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1131518 T5480 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1131540 T5480 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1131541 T5480 oasc.SolrCore.<init> [collection1] Opening new SolrCore at .\org.apache.solr.cloud.MigrateRouteKeyTest-jetty3-1389147009346\collection1\, dataDir=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty3\
   [junit4]   2> 1131541 T5480 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2b1c58cc
   [junit4]   2> 1131542 T5480 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty3\
   [junit4]   2> 1131542 T5480 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty3\index/
   [junit4]   2> 1131542 T5480 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670\jetty3\index' doesn't exist. Creating new index...
   [junit4]   2> 1131543 T5480 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.MigrateRouteKeyTest-1389147000670/jetty3\index
   [junit4]   2> 1131543 T5480 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=15, maxMergeAtOnceExplicit=49, maxMergedSegmentMB=82.6357421875, floorSegmentMB=1.2548828125, forceMergeDeletesPctAllowed=28.67659816569696, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8753618963937313
   [junit4]   2> 1131544 T5480 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@74b30061 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@427759e8),segFN=segments_1,generation=1}
   [junit4]   2> 1131544 T5480 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1131548 T5480 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 1131548 T5480 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 1131549 T5480 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1131549 T5480 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1131549 T5480 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1131549 T5480 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 1131551 T5480 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1131551 T5480 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1131551 T5480 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1131552 T5480 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1131552 T5480 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1131552 T5480 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1131552 T5480 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1131553 T5480 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1131553 T5480 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1131553 T5480 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 1131553 T5480 oasc.RequestHandlers.initHandlersFromConfig created /admin/fileedit: solr.admin.EditFileRequestHandler
   [junit4]   2> 1131558 T5480 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1131560 T5480 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1131560 T5480 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1131562 T5480 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=26.814453125, floorSegmentMB=1.2529296875, forceMergeDeletesPctAllowed=7.506434250323016, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 1131562 T5480 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RA

[...truncated too long message...]


   [junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
   [junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
   [junit4]   2> 
   [junit4]   2> 1164872 T5498 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
   [junit4]   2> 1164926 T5518 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@45e97505 name:ZooKeeperConnection Watcher:127.0.0.1:52999/solr got event WatchedEvent state:Disconnected type:None path:null path:null type:None
   [junit4]   2> 1164926 T5518 oascc.ConnectionManager.process zkClient has disconnected
   [junit4]   2> 1164926 T5399 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 53006
   [junit4]   2> 1164949 T5399 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
   [junit4]   2> 1164949 T5399 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:52999 52999
   [junit4]   1>                   "core":"migrate_multipleshardtest_targetCollection_shard1_replica1",
   [junit4]   1>                   "node_name":"127.0.0.1:53036_",
   [junit4]   1>                   "leader":"true"}}}},
   [junit4]   1>           "router":{"name":"compositeId"},
   [junit4]   1>           "maxShardsPerNode":"5"}}
   [junit4]   1> 
   [junit4]   2> 1164955 T5399 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> 44744 T5398 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
   [junit4]   2> 64831 T5398 ccr.ThreadLeakControl.checkThreadLeaks SEVERE 1 thread leaked from SUITE scope at org.apache.solr.cloud.MigrateRouteKeyTest: 
   [junit4]   2> 	   1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
   [junit4]   2> 	        at java.lang.Object.wait(Native Method)
   [junit4]   2> 	        at java.lang.Object.wait(Object.java:502)
   [junit4]   2> 	        at java.util.TimerThread.mainLoop(Timer.java:526)
   [junit4]   2> 	        at java.util.TimerThread.run(Timer.java:505)
   [junit4]   2> 64831 T5398 ccr.ThreadLeakControl.tryToInterruptAll Starting to interrupt leaked threads:
   [junit4]   2> 	   1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
   [junit4]   2> 68002 T5398 ccr.ThreadLeakControl.tryToInterruptAll SEVERE There are still zombie threads that couldn't be terminated:
   [junit4]   2> 	   1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
   [junit4]   2> 	        at java.lang.Object.wait(Native Method)
   [junit4]   2> 	        at java.lang.Object.wait(Object.java:502)
   [junit4]   2> 	        at java.util.TimerThread.mainLoop(Timer.java:526)
   [junit4]   2> 	        at java.util.TimerThread.run(Timer.java:505)
   [junit4]   2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=th_TH, timezone=Atlantic/Faeroe
   [junit4]   2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=2,threads=2,free=154166304,total=502267904
   [junit4]   2> NOTE: All tests run in this JVM: [TestPseudoReturnFields, TestNoOpRegenerator, DistributedSpellCheckComponentTest, TestPHPSerializedResponseWriter, TestUniqueKeyFieldResource, DistanceFunctionTest, TestCodecSupport, TestRangeQuery, TestRTGBase, SolrCoreCheckLockOnStartupTest, NotRequiredUniqueKeyTest, ScriptEngineTest, TestValueSourceCache, CSVRequestHandlerTest, TestPhraseSuggestions, TestSort, HdfsUnloadDistributedZkTest, TestCloudManagedSchema, PrimitiveFieldTypeTest, RegexBoostProcessorTest, JsonLoaderTest, DistributedTermsComponentTest, BasicDistributedZk2Test, TestJmxMonitoredMap, TestExtendedDismaxParser, TestModifyConfFiles, TestFastOutputStream, TestCoreContainer, TestManagedSchemaFieldResource, TestSuggestSpellingConverter, PingRequestHandlerTest, UpdateParamsTest, TestRandomDVFaceting, TestSolrJ, SOLR749Test, TestSystemIdResolver, TestRecovery, PeerSyncTest, TestShardHandlerFactory, TestBadConfig, CollectionsAPIDistributedZkTest, FunctionTest, TestSolrIndexConfig, TestCollationFieldDocValues, PolyFieldTest, HdfsBasicDistributedZkTest, DOMUtilTest, TestFastWriter, TestSolr4Spatial, ParsingFieldUpdateProcessorsTest, TestUpdate, ZkSolrClientTest, TestHashPartitioner, QueryFacetTest, TestQuerySenderNoQuery, TestZkChroot, ModifyConfFileTest, BadComponentTest, CurrencyFieldOpenExchangeTest, OutputWriterTest, TestFieldTypeResource, RAMDirectoryFactoryTest, OpenCloseCoreStressTest, XmlUpdateRequestHandlerTest, CachingDirectoryFactoryTest, TestLuceneMatchVersion, DocValuesMissingTest, SolrRequestParserTest, TestDefaultSimilarityFactory, TestFileDictionaryLookup, TestReplicationHandler, TestCopyFieldCollectionResource, AddSchemaFieldsUpdateProcessorFactoryTest, SuggesterFSTTest, EnumFieldTest, ExternalFileFieldSortTest, BadIndexSchemaTest, SpellingQueryConverterTest, CursorMarkTest, TestSimpleQParserPlugin, DistributedQueryComponentCustomSortTest, TestStressUserVersions, RequiredFieldsTest, SuggesterTest, SolrIndexSplitterTest, SpellPossibilityIteratorTest, QueryParsingTest, TestImplicitCoreProperties, PreAnalyzedUpdateProcessorTest, CopyFieldTest, TestCustomSort, SliceStateUpdateTest, TestClassNameShortening, TestDistribDocBasedVersion, FullSolrCloudDistribCmdsTest, ClusterStateUpdateTest, DistributedSuggestComponentTest, HardAutoCommitTest, AlternateDirectoryTest, TestDFRSimilarityFactory, AddBlockUpdateTest, WordBreakSolrSpellCheckerTest, MinimalSchemaTest, CursorPagingTest, OverseerTest, BinaryUpdateRequestHandlerTest, IndexSchemaTest, TestSolrCoreProperties, TestSerializedLuceneMatchVersion, MoreLikeThisHandlerTest, TestLazyCores, TestDefaultSearchFieldResource, HighlighterConfigTest, TestFaceting, AnalysisAfterCoreReloadTest, TriLevelCompositeIdRoutingTest, ZkCLITest, SuggesterWFSTTest, TestNumberUtils, QueryElevationComponentTest, TestFiltering, TestFoldingMultitermQuery, TestStressRecovery, SearchHandlerTest, BadCopyFieldTest, SolrTestCaseJ4Test, PluginInfoTest, PathHierarchyTokenizerFactoryTest, TestSchemaSimilarityResource, TestSolrQueryParserDefaultOperatorResource, CoreAdminCreateDiscoverTest, TestElisionMultitermQuery, ShardRoutingTest, SpellCheckCollatorTest, ConvertedLegacyTest, HdfsLockFactoryTest, NoCacheHeaderTest, DistribCursorPagingTest, InfoHandlerTest, RequestHandlersTest, DebugComponentTest, TestInfoStreamLogging, TestComponentsName, TestCoreDiscovery, TestSchemaVersionResource, TestWordDelimiterFilterFactory, TestCursorMarkWithoutUniqueKey, TestNonNRTOpen, TestDocBasedVersionConstraints, TestPostingsSolrHighlighter, FastVectorHighlighterTest, SpellCheckComponentTest, QueryEqualityTest, CoreContainerCoreInitFailuresTest, TestJmxIntegration, SimplePostToolTest, TestSolrXMLSerializer, DirectSolrSpellCheckerTest, DirectUpdateHandlerTest, TestSweetSpotSimilarityFactory, TestDynamicFieldCollectionResource, MultiTermTest, DirectSolrConnectionTest, TestIndexSearcher, HighlighterTest, SolrIndexConfigTest, MigrateRouteKeyTest]
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=MigrateRouteKeyTest -Dtests.seed=ACB193B066BABF80 -Dtests.slow=true -Dtests.locale=th_TH -Dtests.timezone=Atlantic/Faeroe -Dtests.file.encoding=Cp1252
   [junit4] ERROR   0.00s | MigrateRouteKeyTest (suite) <<<
   [junit4]    > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.MigrateRouteKeyTest: 
   [junit4]    >    1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
   [junit4]    >         at java.lang.Object.wait(Native Method)
   [junit4]    >         at java.lang.Object.wait(Object.java:502)
   [junit4]    >         at java.util.TimerThread.mainLoop(Timer.java:526)
   [junit4]    >         at java.util.TimerThread.run(Timer.java:505)
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([ACB193B066BABF80]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
   [junit4]    >    1) Thread[id=5535, name=Timer-10, state=WAITING, group=TGRP-MigrateRouteKeyTest]
   [junit4]    >         at java.lang.Object.wait(Native Method)
   [junit4]    >         at java.lang.Object.wait(Object.java:502)
   [junit4]    >         at java.util.TimerThread.mainLoop(Timer.java:526)
   [junit4]    >         at java.util.TimerThread.run(Timer.java:505)
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([ACB193B066BABF80]:0)
   [junit4] Completed in 68.05s, 1 test, 2 errors <<< FAILURES!

[...truncated 576 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:453: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:433: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\extra-targets.xml:37: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:189: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:491: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1304: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:937: There were test failures: 362 suites, 1586 tests, 2 suite-level errors, 693 ignored (7 assumptions)

Total time: 46 minutes 0 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b121 -XX:+UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure