lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 369 - Still Failing
Date Tue, 03 Sep 2013 07:19:28 GMT
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/369/

1 tests failed.
REGRESSION:  org.apache.solr.handler.TestReplicationHandler.doTestStressReplication

Error Message:
timed out waiting for collection1 startAt time to exceed: Tue Sep 03 03:14:50 EDT 2013

Stack Trace:
java.lang.AssertionError: timed out waiting for collection1 startAt time to exceed: Tue Sep 03 03:14:50 EDT 2013
	at __randomizedtesting.SeedInfo.seed([FBBDEBB21FA00D02:2016EB741A8864B1]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.handler.TestReplicationHandler.watchCoreStartAt(TestReplicationHandler.java:1514)
	at org.apache.solr.handler.TestReplicationHandler.doTestStressReplication(TestReplicationHandler.java:818)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:724)




Build Log:
[...truncated 10287 lines...]
   [junit4] Suite: org.apache.solr.handler.TestReplicationHandler
   [junit4]   2> 1893456 T5710 oas.SolrTestCaseJ4.setUp ###Starting testEmptyCommits
   [junit4]   2> 1893475 T5710 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1893479 T5710 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:50998
   [junit4]   2> 1893480 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1893480 T5710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1893481 T5710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master
   [junit4]   2> 1893481 T5710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/'
   [junit4]   2> 1893516 T5710 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/solr.xml
   [junit4]   2> 1893607 T5710 oasc.CoreContainer.<init> New CoreContainer 1088207739
   [junit4]   2> 1893608 T5710 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/]
   [junit4]   2> 1893610 T5710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1893610 T5710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1893610 T5710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1893611 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1893611 T5710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1893612 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1893612 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1893612 T5710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1893613 T5710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1893613 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1893630 T5710 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1893631 T5710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1893637 T5720 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1
   [junit4]   2> 1893637 T5720 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/'
   [junit4]   2> 1893687 T5720 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1893741 T5720 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1893741 T5720 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1893748 T5720 oass.IndexSchema.readSchema [null] Schema name=test
   [junit4]   2> 1893770 T5720 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1893771 T5720 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1893772 T5720 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/, dataDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/
   [junit4]   2> 1893772 T5720 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
   [junit4]   2> 1893773 T5720 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data
   [junit4]   2> 1893773 T5720 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index/
   [junit4]   2> 1893773 T5720 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index' doesn't exist. Creating new index...
   [junit4]   2> 1893773 T5720 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index
   [junit4]   2> 1893774 T5720 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=20, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 1893775 T5720 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_1,generation=1}
   [junit4]   2> 1893775 T5720 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1893776 T5720 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1893776 T5720 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1893777 T5720 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1893777 T5720 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
   [junit4]   2> 1893777 T5720 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
   [junit4]   2> 1893777 T5720 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
   [junit4]   2> 1893778 T5720 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1893794 T5720 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1893797 T5720 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1893797 T5720 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1893798 T5720 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1129188690, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 1893799 T5720 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_1,generation=1}
   [junit4]   2> 1893799 T5720 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1893799 T5720 oass.SolrIndexSearcher.<init> Opening Searcher@239ab14 main
   [junit4]   2> 1893800 T5720 oash.ReplicationHandler.inform Replication enabled for following config files: schema.xml,xslt/dummy.xsl
   [junit4]   2> 1893800 T5720 oash.ReplicationHandler.inform Commits will be reserved for  10000
   [junit4]   2> 1893800 T5721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@239ab14 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1893800 T5720 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1893801 T5710 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
   [junit4]   2> 1893802 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1893802 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1893825 T5710 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1893828 T5710 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34320
   [junit4]   2> 1893828 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1893829 T5710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1893829 T5710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave
   [junit4]   2> 1893829 T5710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/'
   [junit4]   2> 1893842 T5710 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/solr.xml
   [junit4]   2> 1893900 T5710 oasc.CoreContainer.<init> New CoreContainer 649969713
   [junit4]   2> 1893901 T5710 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/]
   [junit4]   2> 1893903 T5710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1893903 T5710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1893903 T5710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1893904 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1893904 T5710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1893905 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1893905 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1893906 T5710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1893906 T5710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1893907 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1893919 T5710 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1893920 T5710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1893926 T5732 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1
   [junit4]   2> 1893926 T5732 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/'
   [junit4]   2> 1893976 T5732 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1894030 T5732 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1894030 T5732 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1894037 T5732 oass.IndexSchema.readSchema [null] Schema name=test
   [junit4]   2> 1894055 T5732 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1894056 T5732 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1894057 T5732 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/, dataDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/
   [junit4]   2> 1894057 T5732 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
   [junit4]   2> 1894058 T5732 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data
   [junit4]   2> 1894058 T5732 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index/
   [junit4]   2> 1894058 T5732 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index' doesn't exist. Creating new index...
   [junit4]   2> 1894059 T5732 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index
   [junit4]   2> 1894059 T5732 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=20, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 1894060 T5732 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_1,generation=1}
   [junit4]   2> 1894061 T5732 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1894061 T5732 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1894062 T5732 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1894062 T5732 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
   [junit4]   2> 1894062 T5732 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
   [junit4]   2> 1894062 T5732 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
   [junit4]   2> 1894063 T5732 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1894063 T5732 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1894065 T5732 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1894068 T5732 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1894068 T5732 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1894069 T5732 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1129188690, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 1894070 T5732 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_1,generation=1}
   [junit4]   2> 1894070 T5732 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1894070 T5732 oass.SolrIndexSearcher.<init> Opening Searcher@355f6d48 main
   [junit4]   2> 1894071 T5732 oash.SnapPuller.startExecutorService Poll Scheduled at an interval of 1000ms
   [junit4]   2> 1894071 T5733 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@355f6d48 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1894071 T5732 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1894073 T5710 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
   [junit4]   2> 1894073 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1894074 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> ASYNC  NEW_CORE C20293 name=collection1 org.apache.solr.core.SolrCore@7ea22c21
   [junit4]   2> 1894093 T5713 C20293 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 
   [junit4]   2> 1894096 T5713 C20293 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1]} 0 0
   [junit4]   2> 1894099 T5713 C20293 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 1894101 T5713 C20293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_1,generation=1}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_2,generation=2}
   [junit4]   2> 1894101 T5713 C20293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
   [junit4]   2> 1894102 T5713 C20293 oass.SolrIndexSearcher.<init> Opening Searcher@196a804f main
   [junit4]   2> 1894103 T5713 C20293 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 1894103 T5721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@196a804f main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
   [junit4]   2> 1894104 T5713 C20293 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2} {commit=} 0 5
   [junit4]   2> 1894112 T5736 oash.SnapPuller.<init> WARN 'masterUrl' must be specified without the /replication suffix
   [junit4]   2> 1894112 T5736 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
   [junit4]   2> 1894114 T5714 C20293 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
   [junit4]   2> 1894114 T5736 oash.SnapPuller.fetchLatestIndex Master's generation: 2
   [junit4]   2> 1894114 T5736 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
   [junit4]   2> 1894115 T5736 oash.SnapPuller.fetchLatestIndex Starting replication process
   [junit4]   2> 1894119 T5714 C20293 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
   [junit4]   2> 1894119 T5736 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 10
   [junit4]   2> 1894120 T5736 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429893
   [junit4]   2> 1894120 T5736 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5267685b lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4b156685) fullCopy=false
   [junit4]   2> 1894123 T5714 C20293 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> ASYNC  NEW_CORE C20294 name=collection1 org.apache.solr.core.SolrCore@7ea22c21
   [junit4]   2> 1894132 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.dnvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894135 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.dnvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894138 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894141 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894145 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894148 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894152 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894156 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894167 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
   [junit4]   2> 1894168 T5736 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
   [junit4]   2> 1894169 T5736 oasu.DefaultSolrCoreState.closeIndexWriter Closing IndexWriter...
   [junit4]   2> 1894169 T5736 oasu.DefaultSolrCoreState.closeIndexWriter Waiting until IndexWriter is unused... core=collection1
   [junit4]   2> 1894169 T5736 oasu.DefaultSolrCoreState.closeIndexWriter Rollback old IndexWriter... core=collection1
   [junit4]   2> 1894170 T5736 oasu.DefaultSolrCoreState.openIndexWriter Creating new IndexWriter...
   [junit4]   2> 1894170 T5736 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=32, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
   [junit4]   2> 1894171 T5736 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_1,generation=1}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_2,generation=2}
   [junit4]   2> 1894172 T5736 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
   [junit4]   2> 1894172 T5736 oasu.DefaultSolrCoreState.openIndexWriter New IndexWriter is ready to be used.
   [junit4]   2> 1894173 T5736 oass.SolrIndexSearcher.<init> Opening Searcher@40cf7f5f main
   [junit4]   2> 1894173 T5733 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40cf7f5f main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
   [junit4]   2> 1894173 T5736 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429893 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429893;done=true>>]
   [junit4]   2> 1894174 T5736 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429893
   [junit4]   2> ASYNC  NEW_CORE C20295 name=collection1 org.apache.solr.core.SolrCore@376c1a50
   [junit4]   2> 1894174 T5725 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={masterUrl=http://127.0.0.1:50998/solr/replication&command=fetchindex&wait=true} status=0 QTime=63 
   [junit4]   2> 1894177 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:empty1&wt=javabin&version=2} hits=1 status=0 QTime=0 
   [junit4]   2> 1894180 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894183 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894188 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={slave=false&command=details&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894189 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=3 
   [junit4]   2> 1894191 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894193 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894195 T5713 C20294 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 1894195 T5713 C20294 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
   [junit4]   2> 1894196 T5713 C20294 oass.SolrIndexSearcher.<init> Opening Searcher@be4524b main
   [junit4]   2> 1894196 T5713 C20294 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 1894196 T5721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@be4524b main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
   [junit4]   2> 1894197 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2} {commit=} 0 2
   [junit4]   2> 1894198 T5739 oash.SnapPuller.<init> WARN 'masterUrl' must be specified without the /replication suffix
   [junit4]   2> 1894198 T5739 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
   [junit4]   2> 1894201 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
   [junit4]   2> 1894201 T5739 oash.SnapPuller.fetchLatestIndex Slave in sync with master.
   [junit4]   2> 1894202 T5725 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={masterUrl=http://127.0.0.1:50998/solr/replication&command=fetchindex&wait=true} status=0 QTime=5 
   [junit4]   2> 1894204 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[2]} 0 0
   [junit4]   2> 1894207 T5713 C20294 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 1894208 T5713 C20294 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_3,generation=3}
   [junit4]   2> 1894208 T5713 C20294 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
   [junit4]   2> 1894209 T5713 C20294 oass.SolrIndexSearcher.<init> Opening Searcher@2a97f81d main
   [junit4]   2> 1894209 T5713 C20294 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 1894209 T5721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2a97f81d main{StandardDirectoryReader(segments_3:5:nrt _0(5.0):C1 _1(5.0):C1)}
   [junit4]   2> 1894210 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2} {commit=} 0 3
   [junit4]   2> 1894211 T5740 oash.SnapPuller.<init> WARN 'masterUrl' must be specified without the /replication suffix
   [junit4]   2> 1894211 T5740 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
   [junit4]   2> 1894213 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
   [junit4]   2> 1894213 T5740 oash.SnapPuller.fetchLatestIndex Master's generation: 3
   [junit4]   2> 1894214 T5740 oash.SnapPuller.fetchLatestIndex Slave's generation: 2
   [junit4]   2> 1894214 T5740 oash.SnapPuller.fetchLatestIndex Starting replication process
   [junit4]   2> 1894217 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0 
   [junit4]   2> 1894218 T5740 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 19
   [junit4]   2> 1894218 T5740 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429991
   [junit4]   2> 1894219 T5740 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@126ee574 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@36040edb) fullCopy=false
   [junit4]   2> 1894221 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894222 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvm because it already exists
   [junit4]   2> 1894222 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fnm because it already exists
   [junit4]   2> 1894222 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvd because it already exists
   [junit4]   2> 1894226 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894229 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894232 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.dnvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894235 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894239 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894240 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tim because it already exists
   [junit4]   2> 1894240 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdx because it already exists
   [junit4]   2> 1894240 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.si because it already exists
   [junit4]   2> 1894242 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.dnvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894243 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.doc because it already exists
   [junit4]   2> 1894243 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tip because it already exists
   [junit4]   2> 1894246 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894247 T5740 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdt because it already exists
   [junit4]   2> 1894250 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894260 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_1.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
   [junit4]   2> 1894261 T5740 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
   [junit4]   2> 1894262 T5740 oasu.DefaultSolrCoreState.closeIndexWriter Closing IndexWriter...
   [junit4]   2> 1894262 T5740 oasu.DefaultSolrCoreState.closeIndexWriter Waiting until IndexWriter is unused... core=collection1
   [junit4]   2> 1894262 T5740 oasu.DefaultSolrCoreState.closeIndexWriter Rollback old IndexWriter... core=collection1
   [junit4]   2> 1894263 T5740 oasu.DefaultSolrCoreState.openIndexWriter Creating new IndexWriter...
   [junit4]   2> 1894264 T5740 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=32, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
   [junit4]   2> 1894265 T5740 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_3,generation=3}
   [junit4]   2> 1894265 T5740 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
   [junit4]   2> 1894265 T5740 oasu.DefaultSolrCoreState.openIndexWriter New IndexWriter is ready to be used.
   [junit4]   2> 1894266 T5740 oass.SolrIndexSearcher.<init> Opening Searcher@25ef5484 main
   [junit4]   2> 1894266 T5733 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25ef5484 main{StandardDirectoryReader(segments_3:5:nrt _0(5.0):C1 _1(5.0):C1)}
   [junit4]   2> 1894267 T5740 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429991 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429991;done=true>>]
   [junit4]   2> 1894267 T5740 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030429991
   [junit4]   2> 1894267 T5725 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={masterUrl=http://127.0.0.1:50998/solr/replication&command=fetchindex&wait=true} status=0 QTime=56 
   [junit4]   2> 1894270 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:empty2&wt=javabin&version=2} hits=1 status=0 QTime=0 
   [junit4]   2> 1894273 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894276 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894282 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={slave=false&command=details&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894283 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=4 
   [junit4]   2> 1894286 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894289 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894292 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[3]} 0 0
   [junit4]   2> 1894295 T5713 C20294 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 1894296 T5713 C20294 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_4,generation=4}
   [junit4]   2> 1894296 T5713 C20294 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
   [junit4]   2> 1894297 T5713 C20294 oass.SolrIndexSearcher.<init> Opening Searcher@4a539831 realtime
   [junit4]   2> 1894297 T5713 C20294 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 1894298 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={openSearcher=false&commit=true&wt=javabin&version=2} {commit=} 0 3
   [junit4]   2> 1894299 T5742 oash.SnapPuller.<init> WARN 'masterUrl' must be specified without the /replication suffix
   [junit4]   2> 1894299 T5742 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
   [junit4]   2> 1894301 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
   [junit4]   2> 1894301 T5742 oash.SnapPuller.fetchLatestIndex Master's generation: 4
   [junit4]   2> 1894301 T5742 oash.SnapPuller.fetchLatestIndex Slave's generation: 3
   [junit4]   2> 1894302 T5742 oash.SnapPuller.fetchLatestIndex Starting replication process
   [junit4]   2> 1894304 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=0 
   [junit4]   2> 1894305 T5742 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 28
   [junit4]   2> 1894306 T5742 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430078
   [junit4]   2> 1894306 T5742 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@e4d4790 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@3e54e488) fullCopy=false
   [junit4]   2> 1894308 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894309 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.doc because it already exists
   [junit4]   2> 1894312 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.dnvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894313 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvm because it already exists
   [junit4]   2> 1894313 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvd because it already exists
   [junit4]   2> 1894316 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.dnvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894317 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fnm because it already exists
   [junit4]   2> 1894319 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894322 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.dnvm because it already exists
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.dnvd because it already exists
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.si because it already exists
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.tip because it already exists
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.doc because it already exists
   [junit4]   2> 1894323 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.tim because it already exists
   [junit4]   2> 1894324 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fnm because it already exists
   [junit4]   2> 1894326 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894329 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894333 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894336 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_2.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fdx because it already exists
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fdt because it already exists
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _1.si because it already exists
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tim because it already exists
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdx because it already exists
   [junit4]   2> 1894345 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tip because it already exists
   [junit4]   2> 1894346 T5742 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdt because it already exists
   [junit4]   2> 1894348 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
   [junit4]   2> 1894349 T5742 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
   [junit4]   2> 1894350 T5742 oasu.DefaultSolrCoreState.closeIndexWriter Closing IndexWriter...
   [junit4]   2> 1894350 T5742 oasu.DefaultSolrCoreState.closeIndexWriter Waiting until IndexWriter is unused... core=collection1
   [junit4]   2> 1894350 T5742 oasu.DefaultSolrCoreState.closeIndexWriter Rollback old IndexWriter... core=collection1
   [junit4]   2> 1894351 T5742 oasu.DefaultSolrCoreState.openIndexWriter Creating new IndexWriter...
   [junit4]   2> 1894351 T5742 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=32, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
   [junit4]   2> 1894353 T5742 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=3
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_4,generation=4}
   [junit4]   2> 1894353 T5742 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
   [junit4]   2> 1894353 T5742 oasu.DefaultSolrCoreState.openIndexWriter New IndexWriter is ready to be used.
   [junit4]   2> 1894354 T5742 oass.SolrIndexSearcher.<init> Opening Searcher@2e7d2ebc main
   [junit4]   2> 1894355 T5733 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e7d2ebc main{StandardDirectoryReader(segments_4:7:nrt _0(5.0):C1 _1(5.0):C1 _2(5.0):C1)}
   [junit4]   2> 1894355 T5742 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430078 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430078;done=true>>]
   [junit4]   2> 1894355 T5742 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430078
   [junit4]   2> 1894355 T5725 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={masterUrl=http://127.0.0.1:50998/solr/replication&command=fetchindex&wait=true} status=0 QTime=57 
   [junit4]   2> 1894358 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:empty3&wt=javabin&version=2} hits=0 status=0 QTime=0 
   [junit4]   2> 1894362 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:empty3&wt=javabin&version=2} hits=1 status=0 QTime=0 
   [junit4]   2> 1894365 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[4]} 0 0
   [junit4]   2> 1894368 T5713 C20294 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 1894369 T5713 C20294 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_4,generation=4}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2bf79069 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@a29f40c)),segFN=segments_5,generation=5}
   [junit4]   2> 1894370 T5713 C20294 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
   [junit4]   2> 1894370 T5713 C20294 oass.SolrIndexSearcher.<init> Opening Searcher@79ba3fb3 main
   [junit4]   2> 1894371 T5713 C20294 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 1894371 T5721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79ba3fb3 main{StandardDirectoryReader(segments_5:9:nrt _0(5.0):C1 _1(5.0):C1 _2(5.0):C1 _3(5.0):C1)}
   [junit4]   2> 1894371 T5713 C20294 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2} {commit=} 0 3
   [junit4]   2> 1894372 T5744 oash.SnapPuller.<init> WARN 'masterUrl' must be specified without the /replication suffix
   [junit4]   2> 1894373 T5744 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
   [junit4]   2> 1894375 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
   [junit4]   2> 1894375 T5744 oash.SnapPuller.fetchLatestIndex Master's generation: 5
   [junit4]   2> 1894376 T5744 oash.SnapPuller.fetchLatestIndex Slave's generation: 4
   [junit4]   2> 1894376 T5744 oash.SnapPuller.fetchLatestIndex Starting replication process
   [junit4]   2> 1894378 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=5&version=2} status=0 QTime=0 
   [junit4]   2> 1894379 T5744 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 37
   [junit4]   2> 1894379 T5744 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430152
   [junit4]   2> 1894380 T5744 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@569b9f29 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@60997491) fullCopy=false
   [junit4]   2> 1894380 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.si because it already exists
   [junit4]   2> 1894380 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.doc because it already exists
   [junit4]   2> 1894380 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.dnvd because it already exists
   [junit4]   2> 1894381 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvm because it already exists
   [junit4]   2> 1894384 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894385 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.dnvd because it already exists
   [junit4]   2> 1894388 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894391 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894392 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.dnvm because it already exists
   [junit4]   2> 1894392 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fnm because it already exists
   [junit4]   2> 1894392 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.doc because it already exists
   [junit4]   2> 1894392 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.tim because it already exists
   [junit4]   2> 1894392 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.dnvm because it already exists
   [junit4]   2> 1894395 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.dnvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894396 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.dnvd because it already exists
   [junit4]   2> 1894396 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.si because it already exists
   [junit4]   2> 1894396 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.tip because it already exists
   [junit4]   2> 1894396 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.doc because it already exists
   [junit4]   2> 1894396 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.tim because it already exists
   [junit4]   2> 1894399 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.dnvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894400 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fnm because it already exists
   [junit4]   2> 1894400 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.fdt because it already exists
   [junit4]   2> 1894403 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894404 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.fdx because it already exists
   [junit4]   2> 1894404 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.fnm because it already exists
   [junit4]   2> 1894407 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _2.tip because it already exists
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fdx because it already exists
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.fdt because it already exists
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _1.si because it already exists
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tim because it already exists
   [junit4]   2> 1894408 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdx because it already exists
   [junit4]   2> 1894411 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894415 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=_3.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894425 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={file=segments_5&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0 
   [junit4]   2> 1894426 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.tip because it already exists
   [junit4]   2> 1894426 T5744 oash.SnapPuller.downloadIndexFiles Skipping download for _0.fdt because it already exists
   [junit4]   2> 1894426 T5744 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
   [junit4]   2> 1894427 T5744 oasu.DefaultSolrCoreState.closeIndexWriter Closing IndexWriter...
   [junit4]   2> 1894427 T5744 oasu.DefaultSolrCoreState.closeIndexWriter Waiting until IndexWriter is unused... core=collection1
   [junit4]   2> 1894427 T5744 oasu.DefaultSolrCoreState.closeIndexWriter Rollback old IndexWriter... core=collection1
   [junit4]   2> 1894428 T5744 oasu.DefaultSolrCoreState.openIndexWriter Creating new IndexWriter...
   [junit4]   2> 1894429 T5744 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=32, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
   [junit4]   2> 1894430 T5744 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=4
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_4,generation=4}
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@609478d2 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@33885487)),segFN=segments_5,generation=5}
   [junit4]   2> 1894431 T5744 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
   [junit4]   2> 1894431 T5744 oasu.DefaultSolrCoreState.openIndexWriter New IndexWriter is ready to be used.
   [junit4]   2> 1894432 T5744 oass.SolrIndexSearcher.<init> Opening Searcher@2400a2e7 main
   [junit4]   2> 1894432 T5733 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2400a2e7 main{StandardDirectoryReader(segments_5:9:nrt _0(5.0):C1 _1(5.0):C1 _2(5.0):C1 _3(5.0):C1)}
   [junit4]   2> 1894433 T5744 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430152 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430152;done=true>>]
   [junit4]   2> 1894433 T5744 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index.20130903030430152
   [junit4]   2> 1894433 T5725 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={masterUrl=http://127.0.0.1:50998/solr/replication&command=fetchindex&wait=true} status=0 QTime=61 
   [junit4]   2> 1894437 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:(empty1+empty2+empty3+empty4)&wt=javabin&version=2} hits=4 status=0 QTime=0 
   [junit4]   2> 1894440 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={sort=id+desc&q=name:(empty1+empty2+empty3+empty4)&wt=javabin&version=2} hits=4 status=0 QTime=0 
   [junit4]   2> 1894444 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894448 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894453 T5714 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={slave=false&command=details&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894454 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details&_trace=getDetails&wt=javabin&qt=/replication&version=2} status=0 QTime=3 
   [junit4]   2> 1894457 T5713 C20294 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894459 T5726 C20295 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=indexversion&_trace=assertVersions&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
   [junit4]   2> 1894459 T5710 oas.SolrTestCaseJ4.tearDown ###Ending testEmptyCommits
   [junit4]   2> 1894460 T5710 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1088207739
   [junit4]   2> 1894461 T5710 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@7ea22c21
   [junit4]   2> 1894461 T5710 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=5,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=4,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
   [junit4]   2> 1894462 T5710 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 1894462 T5710 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 1894462 T5710 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 1894464 T5710 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 1894464 T5710 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 1894465 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data;done=false>>]
   [junit4]   2> 1894465 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data
   [junit4]   2> 1894465 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index;done=false>>]
   [junit4]   2> 1894466 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869229/master/collection1/data/index
   [junit4]   2> 1894469 T5710 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 1894524 T5710 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=649969713
   [junit4]   2> 1894525 T5710 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@376c1a50
   [junit4]   2> 1894525 T5710 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
   [junit4]   2> 1894526 T5710 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 1894526 T5710 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 1894526 T5710 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 1894528 T5710 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 1894528 T5710 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 1894528 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data;done=false>>]
   [junit4]   2> 1894529 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data
   [junit4]   2> 1894529 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index;done=false>>]
   [junit4]   2> 1894530 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191869587/slave/collection1/data/index
   [junit4]   2> 1894532 T5710 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 1894601 T5710 oas.SolrTestCaseJ4.setUp ###Starting doTestReplicateAfterStartupWithNoActivity
   [junit4]   2> 1894619 T5710 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1894623 T5710 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57641
   [junit4]   2> 1894623 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1894624 T5710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1894624 T5710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master
   [junit4]   2> 1894624 T5710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/'
   [junit4]   2> 1894660 T5710 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/solr.xml
   [junit4]   2> 1894745 T5710 oasc.CoreContainer.<init> New CoreContainer 573976684
   [junit4]   2> 1894746 T5710 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/]
   [junit4]   2> 1894747 T5710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1894748 T5710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1894748 T5710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1894749 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1894749 T5710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1894749 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1894750 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1894750 T5710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1894750 T5710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1894751 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1894768 T5710 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1894768 T5710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1894774 T5755 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1
   [junit4]   2> 1894774 T5755 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/'
   [junit4]   2> 1894824 T5755 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1894884 T5755 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1894884 T5755 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1894891 T5755 oass.IndexSchema.readSchema [null] Schema name=test
   [junit4]   2> 1894913 T5755 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1894915 T5755 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1894915 T5755 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/, dataDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/data/
   [junit4]   2> 1894915 T5755 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
   [junit4]   2> 1894916 T5755 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/data
   [junit4]   2> 1894916 T5755 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/data/index/
   [junit4]   2> 1894916 T5755 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/data/index' doesn't exist. Creating new index...
   [junit4]   2> 1894917 T5755 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870375/master/collection1/data/index
   [junit4]   2> 1894917 T5755 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=20, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 1894918 T5755 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@e03a12e lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@104ada32)),segFN=segments_1,generation=1}
   [junit4]   2> 1894918 T5755 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1894919 T5755 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 1894920 T5755 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1894920 T5755 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1894920 T5755 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
   [junit4]   2> 1894921 T5755 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
   [junit4]   2> 1894921 T5755 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
   [junit4]   2> 1894921 T5755 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1894938 T5755 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1894941 T5755 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1894941 T5755 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1894942 T5755 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1129188690, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 1894942 T5755 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@e03a12e lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@104ada32)),segFN=segments_1,generation=1}
   [junit4]   2> 1894943 T5755 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1894943 T5755 oass.SolrIndexSearcher.<init> Opening Searcher@4065981a main
   [junit4]   2> 1894943 T5755 oash.ReplicationHandler.inform Replication enabled for following config files: schema.xml,xslt/dummy.xsl
   [junit4]   2> 1894944 T5755 oash.ReplicationHandler.inform Commits will be reserved for  10000
   [junit4]   2> 1894944 T5756 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4065981a main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 1894944 T5755 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1894945 T5710 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
   [junit4]   2> 1894946 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1894946 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1894967 T5710 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1894970 T5710 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:17562
   [junit4]   2> 1894970 T5710 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1894971 T5710 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1894971 T5710 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave
   [junit4]   2> 1894971 T5710 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave/'
   [junit4]   2> 1894984 T5710 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave/solr.xml
   [junit4]   2> 1895040 T5710 oasc.CoreContainer.<init> New CoreContainer 1015193041
   [junit4]   2> 1895041 T5710 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave/]
   [junit4]   2> 1895043 T5710 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1895043 T5710 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1895043 T5710 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1895044 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1895044 T5710 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1895045 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1895045 T5710 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1895045 T5710 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1895046 T5710 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1895046 T5710 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1895056 T5710 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1895056 T5710 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1895062 T5767 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave/collection1
   [junit4]   2> 1895062 T5767 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378191870729/slave/collection1/'
   [junit4]   2> 1895112 T5767 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 1895164 T5767 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1895165 T5767 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1895171 T5767 oass.IndexSchema.readSchema [null] Schema name=test
   [junit4]   2> 1895189 T5767 oass.IndexSchema.readSchema unique key field: id
 

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

app=/solr path=/replication params={command=details} status=0 QTime=1 
   [junit4]   2> 2581075 T6439 C20648 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0 
   [junit4]   2> 2581086 T5710 oas.SolrTestCaseJ4.tearDown ###Ending doTestBackup
   [junit4]   2> 2581087 T5710 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=378555149
   [junit4]   2> 2581088 T5710 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@49ecd992
   [junit4]   2> 2581088 T5710 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=492,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
   [junit4]   2> 2581089 T5710 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 2581089 T5710 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 2581089 T5710 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 2581091 T5710 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 2581091 T5710 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 2581091 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data;done=false>>]
   [junit4]   2> 2581092 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data
   [junit4]   2> 2581092 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data/index;done=false>>]
   [junit4]   2> 2581093 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553299/master/collection1/data/index
   [junit4]   2> 2581096 T5710 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 2581149 T5710 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=479896176
   [junit4]   2> 2581150 T5710 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@4f325807
   [junit4]   2> 2593229 T6434 oash.SnapPuller.fetchLatestIndex ERROR Master at: http://127.0.0.1:31316/solr is not available. Index fetch failed. Exception: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:31316/solr
   [junit4]   2> 2593230 T5710 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
   [junit4]   2> 2593231 T5710 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 2593232 T5710 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 2593232 T5710 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 2593233 T5710 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 2593233 T5710 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 2593234 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data;done=false>>]
   [junit4]   2> 2593234 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data
   [junit4]   2> 2593235 T5710 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data/index;done=false>>]
   [junit4]   2> 2593235 T5710 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.handler.TestReplicationHandler$SolrInstance-1378192553655/slave/collection1/data/index
   [junit4]   2> 2593236 T5710 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 2593300 T5710 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=ar_TN, timezone=US/Michigan
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=16,threads=1,free=225975184,total=493748224
   [junit4]   2> NOTE: All tests run in this JVM: [TestCloudManagedSchemaAddField, TestLMJelinekMercerSimilarityFactory, FieldMutatingUpdateProcessorTest, LeaderElectionTest, TestSchemaVersionResource, SampleTest, TestSurroundQueryParser, LegacyHTMLStripCharFilterTest, ReturnFieldsTest, SoftAutoCommitTest, TestNoOpRegenerator, SolrCoreTest, TestPerFieldSimilarity, TestElisionMultitermQuery, SliceStateUpdateTest, BasicDistributedZkTest, OverseerTest, TestSolrQueryParserResource, DistributedSpellCheckComponentTest, FileBasedSpellCheckerTest, TestTrie, TestSolrXMLSerializer, OverseerCollectionProcessorTest, TestLRUCache, TestNRTOpen, UnloadDistributedZkTest, CSVRequestHandlerTest, DocumentBuilderTest, HdfsBasicDistributedZkTest, SpellPossibilityIteratorTest, TestRandomDVFaceting, TestLuceneMatchVersion, QueryEqualityTest, SystemInfoHandlerTest, TestWriterPerf, TestSolrIndexConfig, AssignTest, InfoHandlerTest, TestReversedWildcardFilterFactory, TermsComponentTest, TestFieldTypeResource, TestGroupingSearch, SOLR749Test, AddSchemaFieldsUpdateProcessorFactoryTest, TestFieldResource, HdfsCollectionsAPIDistributedZkTest, SuggesterTest, TestDocumentBuilder, ShardRoutingTest, ResourceLoaderTest, ShowFileRequestHandlerTest, SimpleFacetsTest, PrimitiveFieldTypeTest, DistributedQueryElevationComponentTest, TestConfig, SolrTestCaseJ4Test, ZkCLITest, SynonymTokenizerTest, TestLFUCache, ClusterStateTest, TestSchemaNameResource, SolrXmlInZkTest, QueryElevationComponentTest, TestSolrXml, WordBreakSolrSpellCheckerTest, TestQueryUtils, SolrInfoMBeanTest, UpdateParamsTest, TestSolrDeletionPolicy1, TestJmxMonitoredMap, TestMergePolicyConfig, DocValuesTest, TestRealTimeGet, JsonLoaderTest, TestSystemIdResolver, TestSearchPerf, TestSolrQueryParser, CircularListTest, SyncSliceTest, OpenCloseCoreStressTest, RecoveryZkTest, TestReplicationHandler]
   [junit4] Completed on J0 in 699.88s, 14 tests, 1 failure <<< FAILURES!

[...truncated 123 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:403: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:376: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:455: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1230: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:873: There were test failures: 324 suites, 1410 tests, 1 failure, 33 ignored (4 assumptions)

Total time: 103 minutes 54 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message