You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/08/24 04:20:56 UTC

[JENKINS] Lucene-Solr-trunk-Windows (32bit/jdk1.7.0_25) - Build # 3184 - Failure!

Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/3184/
Java: 32bit/jdk1.7.0_25 -server -XX:+UseConcMarkSweepGC

1 tests failed.
REGRESSION:  org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testUpdateMultiValuedField

Error Message:
IOException occured when talking to server at: https://127.0.0.1:49830/solr/collection1

Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:49830/solr/collection1
	at __randomizedtesting.SeedInfo.seed([CA21D1B8D2B0BFDC:D8245CD301BC6804]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
	at org.apache.solr.client.solrj.SolrExampleTests.testUpdateMultiValuedField(SolrExampleTests.java:1408)
	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)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
	... 44 more




Build Log:
[...truncated 10837 lines...]
   [junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest
   [junit4]   2> 63186 T135 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
   [junit4]   2> 63186 T135 oas.SolrTestCaseJ4.initCore ####initCore
   [junit4]   2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\.\solrtest-SolrExampleJettyTest-1377310444824
   [junit4]   2> 63187 T135 oas.SolrTestCaseJ4.initCore ####initCore end
   [junit4]   2> 63187 T135 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 63198 T135 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
   [junit4]   2> 63202 T135 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:49830
   [junit4]   2> 63202 T135 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 63202 T135 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 63202 T135 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr
   [junit4]   2> 63202 T135 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\'
   [junit4]   2> 63235 T135 oasc.ConfigSolr.fromFile Loading container configuration from C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\solr.xml
   [junit4]   2> 63329 T135 oasc.ConfigSolrXml.<init> Config-defined core root directory: 
   [junit4]   2> 63329 T135 oasc.CoreContainer.<init> New CoreContainer 29910895
   [junit4]   2> 63329 T135 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\]
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 63332 T135 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 63333 T135 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 63333 T135 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 63333 T135 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
   [junit4]   2> 63343 T135 oasc.CorePropertiesLocator.discover Looking for core definitions underneath C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr
   [junit4]   2> 63371 T135 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\
   [junit4]   2> 63372 T135 oasc.CorePropertiesLocator.discover Found 1 core definitions
   [junit4]   2> 63374 T145 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1
   [junit4]   2> 63374 T145 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\'
   [junit4]   2> 63430 T145 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
   [junit4]   2> 63433 T145 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\contrib\extraction\lib).
   [junit4]   2> 63434 T145 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\dist).
   [junit4]   2> 63435 T145 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\contrib\clustering\lib).
   [junit4]   2> 63435 T145 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\dist).
   [junit4]   2> 63435 T145 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\contrib\langid\lib).
   [junit4]   2> 63436 T145 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\dist).
   [junit4]   2> 63437 T145 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\contrib\velocity\lib).
   [junit4]   2> 63437 T145 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\..\..\..\dist).
   [junit4]   2> 63495 T145 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
   [junit4]   2> 63504 T145 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 63600 T145 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 63601 T145 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 63639 T145 oass.IndexSchema.readSchema [null] Schema name=example
   [junit4]   2> 64526 T145 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 64547 T145 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 64553 T145 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 64587 T145 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 64587 T145 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\, dataDir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\
   [junit4]   2> 64587 T145 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e8a06
   [junit4]   2> 64588 T145 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
   [junit4]   2> 64588 T145 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
   [junit4]   2> 64589 T145 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\
   [junit4]   2> 64589 T145 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index/
   [junit4]   2> 64589 T145 oasc.SolrCore.initIndex WARN [collection1] Solr index directory 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index' doesn't exist. Creating new index...
   [junit4]   2> 64589 T145 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index
   [junit4]   2> 64591 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@17506e6
   [junit4]   2> 64591 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 64591 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: 0 msec to checkpoint
   [junit4]   2> 64591 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: init: create=true
   [junit4]   2> 64592 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821)
   [junit4]   2> 	index=
   [junit4]   2> 	version=5.0-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_50
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
   [junit4]   2> 	commit=null
   [junit4]   2> 	openMode=CREATE
   [junit4]   2> 	similarity=org.apache.lucene.search.similarities.DefaultSimilarity
   [junit4]   2> 	mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
   [junit4]   2> 	default WRITE_LOCK_TIMEOUT=1000
   [junit4]   2> 	writeLockTimeout=1000
   [junit4]   2> 	codec=Lucene45
   [junit4]   2> 	infoStream=org.apache.solr.update.LoggingInfoStream
   [junit4]   2> 	mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 	indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@181c21
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 64592 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: now flush at close waitForMerges=true
   [junit4]   2> 64592 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]:   start flush: applyAllDeletes=true
   [junit4]   2> 64592 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]:   index before flush 
   [junit4]   2> 64592 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 startFullFlush
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 finishFullFlush success=true
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: apply all deletes during flush
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-57-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@debb99 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-57-thread-1]: now merge
   [junit4]   2> 64593 T145 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-57-thread-1]:   index: 
   [junit4]   2> 64594 T145 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-57-thread-1]:   no more merges pending; now return
   [junit4]   2> 64594 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: waitForMerges
   [junit4]   2> 64594 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: waitForMerges done
   [junit4]   2> 64595 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: now call final commit()
   [junit4]   2> 64595 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: start
   [junit4]   2> 64595 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: enter lock
   [junit4]   2> 64595 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: now prepare
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: prepareCommit: flush
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]:   index before flush 
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 startFullFlush
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: apply all deletes during flush
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-57-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@debb99 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 finishFullFlush success=true
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: startCommit(): start
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: startCommit index= changeCount=1
   [junit4]   2> 64596 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: done all syncs: []
   [junit4]   2> 64597 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: pendingCommit != null
   [junit4]   2> 64597 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: wrote segments file "segments_1"
   [junit4]   2> 64597 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
   [junit4]   2> 64597 T145 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_1,generation=1}
   [junit4]   2> 64597 T145 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 64598 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: 1 msec to checkpoint
   [junit4]   2> 64598 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: commit: done
   [junit4]   2> 64598 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: at close: 
   [junit4]   2> 64600 T145 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
   [junit4]   2> 64600 T145 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
   [junit4]   2> 64601 T145 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
   [junit4]   2> 64601 T145 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
   [junit4]   2> 64601 T145 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
   [junit4]   2> 64606 T145 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 64606 T145 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
   [junit4]   2> 64607 T145 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
   [junit4]   2> 64607 T145 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 64607 T145 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
   [junit4]   2> 64607 T145 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 64608 T145 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
   [junit4]   2> 64608 T145 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
   [junit4]   2> 64609 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 64609 T145 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 64609 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
   [junit4]   2> 64609 T145 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
   [junit4]   2> 64610 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 64610 T145 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 64610 T145 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
   [junit4]   2> 64611 T145 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
   [junit4]   2> 64611 T145 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
   [junit4]   2> 64612 T145 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 64612 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 64612 T145 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
   [junit4]   2> 64612 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 64612 T145 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
   [junit4]   2> 64613 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
   [junit4]   2> 64613 T145 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
   [junit4]   2> 64613 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 64613 T145 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
   [junit4]   2> 64613 T145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 64614 T145 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
   [junit4]   2> 64624 T145 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 64625 T145 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 64628 T145 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 64637 T145 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms; 
   [junit4]   2> 64637 T145 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 64639 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@17506e6
   [junit4]   2> 64639 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: init: load commit "segments_1"
   [junit4]   2> 64639 T145 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_1,generation=1}
   [junit4]   2> 64639 T145 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 64640 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 64640 T145 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-57-thread-1]: 0 msec to checkpoint
   [junit4]   2> 64640 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: init: create=false
   [junit4]   2> 64640 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821)
   [junit4]   2> 	index=
   [junit4]   2> 	version=5.0-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_50
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
   [junit4]   2> 	commit=null
   [junit4]   2> 	openMode=APPEND
   [junit4]   2> 	similarity=org.apache.lucene.search.similarities.DefaultSimilarity
   [junit4]   2> 	mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
   [junit4]   2> 	default WRITE_LOCK_TIMEOUT=1000
   [junit4]   2> 	writeLockTimeout=1000
   [junit4]   2> 	codec=Lucene45
   [junit4]   2> 	infoStream=org.apache.solr.update.LoggingInfoStream
   [junit4]   2> 	mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 	indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@14d8e1
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 64641 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: flush at getReader
   [junit4]   2> 64641 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 startFullFlush
   [junit4]   2> 64641 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64641 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: apply all deletes during flush
   [junit4]   2> 64642 T145 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-57-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 64642 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
   [junit4]   2> 64642 T145 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-57-thread-1]: coreLoadExecutor-57-thread-1 finishFullFlush success=true
   [junit4]   2> 64642 T145 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-57-thread-1]: getReader took 1 msec
   [junit4]   2> 64643 T145 oass.SolrIndexSearcher.<init> Opening Searcher@17e9172 main
   [junit4]   2> 64643 T145 oashc.SpellCheckComponent.inform Initializing spell checkers
   [junit4]   2> 64643 T145 oass.DirectSolrSpellChecker.init init: {name=default,field=text,classname=solr.DirectSolrSpellChecker,distanceMeasure=internal,accuracy=0.5,maxEdits=2,minPrefix=1,maxInspections=5,minQueryLength=4,maxQueryFrequency=0.01}
   [junit4]   2> 64643 T145 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
   [junit4]   2> 64645 T145 oashc.QueryElevationComponent.inform Loading QueryElevation from: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\example\solr\collection1\conf\elevate.xml
   [junit4]   2> 64683 T145 oash.ReplicationHandler.inform Commits will be reserved for  10000
   [junit4]   2> 64685 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@17e9172 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> ASYNC  NEW_CORE C81 name=collection1 org.apache.solr.core.SolrCore@2ab50f
   [junit4]   2> 64686 T146 C81 oasc.SolrCore.execute [collection1] webapp=null path=null params={event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml&distrib=false} hits=0 status=0 QTime=1 
   [junit4]   2> 64686 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 64686 T146 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
   [junit4]   2> 64686 T146 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
   [junit4]   2> 64688 T146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17e9172 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 64691 T145 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 64692 T135 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0
   [junit4]   2> 64692 T135 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 64692 T135 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#49830
   [junit4]   2> 64699 T135 oas.SolrTestCaseJ4.setUp ###Starting testChineseDefaults
   [junit4]   2> 64700 T135 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 64786 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64786 T143 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-143]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 64786 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64787 T143 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-143]: flush at getReader
   [junit4]   2> 64787 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: qtp20468877-143 startFullFlush
   [junit4]   2> 64787 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64788 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: qtp20468877-143: flush naked frozen global deletes
   [junit4]   2> 64789 T143 C81 oasu.LoggingInfoStream.message [BD][qtp20468877-143]: push deletes  1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
   [junit4]   2> 64789 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 64789 T143 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-143]: apply all deletes during flush
   [junit4]   2> 64790 T143 C81 oasu.LoggingInfoStream.message [BD][qtp20468877-143]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 64790 T143 C81 oasu.LoggingInfoStream.message [BD][qtp20468877-143]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64790 T143 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-143]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
   [junit4]   2> 64791 T143 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-143]: qtp20468877-143 finishFullFlush success=true
   [junit4]   2> 64791 T143 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-143]: getReader took 4 msec
   [junit4]   2> 64792 T143 C81 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444214678663200768)} 0 13
   [junit4]   2> 64797 T144 C81 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 64798 T144 C81 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
   [junit4]   2> 64799 T144 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64799 T144 C81 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
   [junit4]   2> 64800 T144 C81 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64800 T144 C81 oass.SolrIndexSearcher.<init> Opening Searcher@ad5908 main
   [junit4]   2> 64801 T144 C81 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 64801 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@ad5908 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 64801 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 64802 T146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ad5908 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> ASYNC  NEW_CORE C82 name=collection1 org.apache.solr.core.SolrCore@2ab50f
   [junit4]   2> 64809 T144 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 12
   [junit4]   2> 64815 T139 C82 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 
   [junit4]   2> 64824 T140 C82 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: start
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: enter lock
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: now prepare
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: prepareCommit: flush
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]:   index before flush 
   [junit4]   2> 64824 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 startFullFlush
   [junit4]   2> 64825 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64825 T140 C82 oasu.LoggingInfoStream.message [DWFC][qtp20468877-140]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 2 ]]
   [junit4]   2> 64825 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: flush postings as segment _0 numDocs=1
   [junit4]   2> 64826 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: new segment has 0 deleted docs
   [junit4]   2> 64826 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: new segment has no vectors; norms; no docValues; prox; freqs
   [junit4]   2> 64828 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.nvm, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
   [junit4]   2> 64828 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: flushed codec=Lucene45
   [junit4]   2> 64828 T140 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-140]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,230.723
   [junit4]   2> 64828 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 64828 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: publishFlushedSegment
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: push deletes  1 deleted terms (unique count=1) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: publish sets newSegment delGen=5 seg=_0(5.0):C1
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: now checkpoint "_0(5.0):C1" [1 segments ; isCommit = false]
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: 0 msec to checkpoint
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: apply all deletes during flush
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: applyDeletes: infos=[_0(5.0):C1] packetCount=1
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: applyDeletes took 0 msec
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=6 packetCount=1
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64829 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 finishFullFlush success=true
   [junit4]   2> 64831 T140 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-140]: findMerges: 1 segments
   [junit4]   2> 64831 T140 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-140]:   seg=_0(5.0):C1 size=0.001 MB [floored]
   [junit4]   2> 64831 T140 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-140]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 64831 T140 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-140]: now merge
   [junit4]   2> 64832 T140 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-140]:   index: _0(5.0):C1
   [junit4]   2> 64832 T140 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-140]:   no more merges pending; now return
   [junit4]   2> 64832 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: startCommit(): start
   [junit4]   2> 64832 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: startCommit index=_0(5.0):C1 changeCount=3
   [junit4]   2> 64832 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
   [junit4]   2> 64833 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: pendingCommit != null
   [junit4]   2> 64833 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: wrote segments file "segments_2"
   [junit4]   2> 64834 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: now checkpoint "_0(5.0):C1" [1 segments ; isCommit = true]
   [junit4]   2> 64834 T140 C82 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_1,generation=1}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_2,generation=2}
   [junit4]   2> 64834 T140 C82 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
   [junit4]   2> 64835 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: deleteCommits: now decRef commit "segments_1"
   [junit4]   2> 64835 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: delete "segments_1"
   [junit4]   2> 64836 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: 2 msec to checkpoint
   [junit4]   2> 64836 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: commit: done
   [junit4]   2> 64837 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64837 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 64837 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: flush at getReader
   [junit4]   2> 64838 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 startFullFlush
   [junit4]   2> 64838 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64839 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: apply all deletes during flush
   [junit4]   2> 64839 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: applyDeletes: no deletes; skipping
   [junit4]   2> 64839 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=6 packetCount=0
   [junit4]   2> 64840 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)
   [junit4]   2> 64840 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 finishFullFlush success=true
   [junit4]   2> 64841 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: getReader took 4 msec
   [junit4]   2> 64841 T140 C82 oass.SolrIndexSearcher.<init> Opening Searcher@1806f4c main
   [junit4]   2> 64842 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1806f4c main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
   [junit4]   2> 64842 T140 C82 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 64842 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 64846 T146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1806f4c main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
   [junit4]   2> 64846 T140 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {add=[42 (1444214678706192384)],commit=} 0 26
   [junit4]   2> 64854 T141 C82 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=????&wt=javabin&version=2} hits=1 status=0 QTime=2 
   [junit4]   2> 64857 T135 oas.SolrTestCaseJ4.tearDown ###Ending testChineseDefaults
   [junit4]   2> 64871 T135 oas.SolrTestCaseJ4.setUp ###Starting testUnicode
   [junit4]   2> 64876 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64876 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 64877 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64877 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: flush at getReader
   [junit4]   2> 64877 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 startFullFlush
   [junit4]   2> 64877 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64878 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142: flush naked frozen global deletes
   [junit4]   2> 64878 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: push deletes  1 deleted queries bytesUsed=32 delGen=8 packetCount=1 totBytesUsed=32
   [junit4]   2> 64878 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 64878 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: apply all deletes during flush
   [junit4]   2> 64878 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: applyDeletes: infos=[_0(5.0):C1] packetCount=1
   [junit4]   2> 64879 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: seg=_0(5.0):C1 segGen=6 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
   [junit4]   2> 64879 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: applyDeletes took 1 msec
   [junit4]   2> 64879 T142 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: now checkpoint "_0(5.0):C1/1" [1 segments ; isCommit = false]
   [junit4]   2> 64880 T142 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: 0 msec to checkpoint
   [junit4]   2> 64880 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: drop 100% deleted segments: _0(5.0):C1/1
   [junit4]   2> 64880 T142 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 64880 T142 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: 0 msec to checkpoint
   [junit4]   2> 64880 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 64881 T142 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64881 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
   [junit4]   2> 64881 T142 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 finishFullFlush success=true
   [junit4]   2> 64881 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: getReader took 4 msec
   [junit4]   2> 64882 T142 C82 oass.SolrIndexSearcher.<init> Opening Searcher@ef6b04 realtime
   [junit4]   2> 64883 T142 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444214678761766912)} 0 9
   [junit4]   2> 64890 T143 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1444214678776446976), 1 (1444214678777495552), 2 (1444214678777495553), 3 (1444214678777495554), 4 (1444214678777495555), 5 (1444214678777495556), 6 (1444214678777495557), 7 (1444214678777495558)]} 0 2
   [junit4]   2> 64897 T144 C82 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 64897 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: start
   [junit4]   2> 64897 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: enter lock
   [junit4]   2> 64897 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: now prepare
   [junit4]   2> 64897 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: prepareCommit: flush
   [junit4]   2> 64898 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]:   index before flush 
   [junit4]   2> 64898 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: qtp20468877-144 startFullFlush
   [junit4]   2> 64898 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: anyChanges? numDocsInRam=8 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64898 T144 C82 oasu.LoggingInfoStream.message [DWFC][qtp20468877-144]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 7 deleted terms (unique count=7) bytesUsed=959, segment=_1, aborting=false, numDocsInRAM=8, deleteQueue=DWDQ: [ generation: 5 ]]
   [junit4]   2> 64898 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: flush postings as segment _1 numDocs=8
   [junit4]   2> 64899 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: new segment has 0 deleted docs
   [junit4]   2> 64899 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 64899 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: flushedFiles=[_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
   [junit4]   2> 64899 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: flushed codec=Lucene45
   [junit4]   2> 64899 T144 C82 oasu.LoggingInfoStream.message [DWPT][qtp20468877-144]: flushed: segment=_1 ramUsed=0.064 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=5,603.613
   [junit4]   2> 64900 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 64900 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: publishFlushedSegment
   [junit4]   2> 64900 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: push deletes  8 deleted terms (unique count=8) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
   [junit4]   2> 64903 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: publish sets newSegment delGen=11 seg=_1(5.0):C8
   [junit4]   2> 64904 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: now checkpoint "_1(5.0):C8" [1 segments ; isCommit = false]
   [junit4]   2> 64904 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: 0 msec to checkpoint
   [junit4]   2> 64904 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: apply all deletes during flush
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: applyDeletes: infos=[_1(5.0):C8] packetCount=1
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: applyDeletes took 0 msec
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=12 packetCount=1
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: qtp20468877-144 finishFullFlush success=true
   [junit4]   2> 64905 T144 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-144]: findMerges: 1 segments
   [junit4]   2> 64906 T144 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-144]:   seg=_1(5.0):C8 size=0.001 MB [floored]
   [junit4]   2> 64907 T144 C82 oasu.LoggingInfoStream.message [TMP][qtp20468877-144]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 64908 T144 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-144]: now merge
   [junit4]   2> 64908 T144 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-144]:   index: _1(5.0):C8
   [junit4]   2> 64909 T144 C82 oasu.LoggingInfoStream.message [CMS][qtp20468877-144]:   no more merges pending; now return
   [junit4]   2> 64909 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: startCommit(): start
   [junit4]   2> 64910 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: startCommit index=_1(5.0):C8 changeCount=8
   [junit4]   2> 64910 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: done all syncs: [_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
   [junit4]   2> 64910 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: pendingCommit != null
   [junit4]   2> 64911 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: wrote segments file "segments_3"
   [junit4]   2> 64911 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: now checkpoint "_1(5.0):C8" [1 segments ; isCommit = true]
   [junit4]   2> 64912 T144 C82 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_3,generation=3}
   [junit4]   2> 64912 T144 C82 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
   [junit4]   2> 64913 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: deleteCommits: now decRef commit "segments_2"
   [junit4]   2> 64913 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.fnm"
   [junit4]   2> 64913 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 64914 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64914 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 64914 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64914 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.nvd"
   [junit4]   2> 64915 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64915 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "segments_2"
   [junit4]   2> 64916 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.fdx"
   [junit4]   2> 64916 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.si"
   [junit4]   2> 64916 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.nvm"
   [junit4]   2> 64916 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 64916 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64917 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.fdt"
   [junit4]   2> 64918 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64918 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.tip"
   [junit4]   2> 64918 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: 7 msec to checkpoint
   [junit4]   2> 64918 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: commit: done
   [junit4]   2> 64919 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64920 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 64920 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: flush at getReader
   [junit4]   2> 64921 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: qtp20468877-144 startFullFlush
   [junit4]   2> 64921 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64921 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: apply all deletes during flush
   [junit4]   2> 64921 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: applyDeletes: no deletes; skipping
   [junit4]   2> 64921 T144 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-144]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=12 packetCount=0
   [junit4]   2> 64922 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(5.0):C8)
   [junit4]   2> 64923 T144 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-144]: qtp20468877-144 finishFullFlush success=true
   [junit4]   2> 64923 T144 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-144]: getReader took 3 msec
   [junit4]   2> 64924 T144 C82 oass.SolrIndexSearcher.<init> Opening Searcher@16bae16 main
   [junit4]   2> 64924 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 64924 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 64925 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64926 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 64926 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 64926 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64927 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete pending file _0.nvd
   [junit4]   2> 64927 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.nvd"
   [junit4]   2> 64927 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64927 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 64928 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 64928 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64928 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete pending file _0.fdt
   [junit4]   2> 64929 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: delete "_0.fdt"
   [junit4]   2> 64929 T144 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-144]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64930 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@16bae16 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C8)}
   [junit4]   2> 64930 T144 C82 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 64931 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 64932 T146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16bae16 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C8)}
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _0.nvd
   [junit4]   2> 64933 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_0.nvd"
   [junit4]   2> 64934 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 64934 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 64934 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _0.fdt
   [junit4]   2> 64934 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_0.fdt"
   [junit4]   2> 64935 T144 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 38
   [junit4]   2> 64938 T139 C82 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2&rows=8} hits=8 status=0 QTime=0 
   [junit4]   2> 64946 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64947 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 64947 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64947 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: flush at getReader
   [junit4]   2> 64948 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 startFullFlush
   [junit4]   2> 64948 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64948 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140: flush naked frozen global deletes
   [junit4]   2> 64949 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: push deletes  1 deleted queries bytesUsed=32 delGen=14 packetCount=1 totBytesUsed=32
   [junit4]   2> 64949 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 64949 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: apply all deletes during flush
   [junit4]   2> 64950 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: applyDeletes: infos=[_1(5.0):C8] packetCount=1
   [junit4]   2> 64950 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: seg=_1(5.0):C8 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=8 100% deleted
   [junit4]   2> 64951 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: applyDeletes took 1 msec
   [junit4]   2> 64952 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: now checkpoint "_1(5.0):C8/8" [1 segments ; isCommit = false]
   [junit4]   2> 64952 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: 0 msec to checkpoint
   [junit4]   2> 64952 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: drop 100% deleted segments: _1(5.0):C8/8
   [junit4]   2> 64953 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 64953 T140 C82 oasu.LoggingInfoStream.message [IFD][qtp20468877-140]: 0 msec to checkpoint
   [junit4]   2> 64954 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 64954 T140 C82 oasu.LoggingInfoStream.message [BD][qtp20468877-140]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64954 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
   [junit4]   2> 64954 T140 C82 oasu.LoggingInfoStream.message [DW][qtp20468877-140]: qtp20468877-140 finishFullFlush success=true
   [junit4]   2> 64954 T140 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-140]: getReader took 7 msec
   [junit4]   2> 64955 T140 C82 oass.SolrIndexSearcher.<init> Opening Searcher@224038 realtime
   [junit4]   2> 64956 T140 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444214678835167232)} 0 12
   [junit4]   2> 64962 T141 C82 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1444214678851944448)]} 0 2
   [junit4]   2> 64966 T142 C82 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 64966 T142 C82 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: start
   [junit4]   2> ASYNC  NEW_CORE C83 name=collection1 org.apache.solr.core.SolrCore@2ab50f
   [junit4]   2> 64966 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: enter lock
   [junit4]   2> 64971 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: now prepare
   [junit4]   2> 64971 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: prepareCommit: flush
   [junit4]   2> 64971 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]:   index before flush 
   [junit4]   2> 64971 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 startFullFlush
   [junit4]   2> 64972 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64972 T142 C83 oasu.LoggingInfoStream.message [DWFC][qtp20468877-142]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 8 ]]
   [junit4]   2> 64972 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: flush postings as segment _2 numDocs=1
   [junit4]   2> 64974 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: new segment has 0 deleted docs
   [junit4]   2> 64974 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: flushedFiles=[_2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: flushed codec=Lucene45
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-142]: flushed: segment=_2 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,502.258
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: publishFlushedSegment
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: push deletes  1 deleted terms (unique count=1) bytesUsed=1024 delGen=16 packetCount=1 totBytesUsed=1024
   [junit4]   2> 64975 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: publish sets newSegment delGen=17 seg=_2(5.0):C1
   [junit4]   2> 64976 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: now checkpoint "_2(5.0):C1" [1 segments ; isCommit = false]
   [junit4]   2> 64976 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: 0 msec to checkpoint
   [junit4]   2> 64977 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: apply all deletes during flush
   [junit4]   2> 64977 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: applyDeletes: infos=[_2(5.0):C1] packetCount=1
   [junit4]   2> 64977 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: applyDeletes took 0 msec
   [junit4]   2> 64977 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=18 packetCount=1
   [junit4]   2> 64977 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 64978 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 finishFullFlush success=true
   [junit4]   2> 64978 T142 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-142]: findMerges: 1 segments
   [junit4]   2> 64978 T142 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-142]:   seg=_2(5.0):C1 size=0.000 MB [floored]
   [junit4]   2> 64978 T142 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-142]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 64979 T142 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-142]: now merge
   [junit4]   2> 64979 T142 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-142]:   index: _2(5.0):C1
   [junit4]   2> 64980 T142 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-142]:   no more merges pending; now return
   [junit4]   2> 64980 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: startCommit(): start
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: startCommit index=_2(5.0):C1 changeCount=13
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: done all syncs: [_2.si, _2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: pendingCommit != null
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: wrote segments file "segments_4"
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: now checkpoint "_2(5.0):C1" [1 segments ; isCommit = true]
   [junit4]   2> 64981 T142 C83 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2aebf lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b5821),segFN=segments_4,generation=4}
   [junit4]   2> 64981 T142 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: deleteCommits: now decRef commit "segments_3"
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1.fdx"
   [junit4]   2> 64981 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 64982 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64982 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1.fdt"
   [junit4]   2> 64983 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64983 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1.si"
   [junit4]   2> 64984 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 64984 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64985 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1_Lucene41_0.tip"
   [junit4]   2> 64985 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1.fnm"
   [junit4]   2> 64985 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "segments_3"
   [junit4]   2> 64985 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: 4 msec to checkpoint
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: commit: done
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: flush at getReader
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 startFullFlush
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: apply all deletes during flush
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: applyDeletes: no deletes; skipping
   [junit4]   2> 64986 T142 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-142]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=18 packetCount=0
   [junit4]   2> 64988 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: return reader version=11 reader=StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)
   [junit4]   2> 64988 T142 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-142]: qtp20468877-142 finishFullFlush success=true
   [junit4]   2> 64989 T142 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-142]: getReader took 3 msec
   [junit4]   2> 64989 T142 C83 oass.SolrIndexSearcher.<init> Opening Searcher@1679451 main
   [junit4]   2> 64989 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete pending file _1_Lucene41_0.doc
   [junit4]   2> 64989 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 64990 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64990 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete pending file _1.fdt
   [junit4]   2> 64990 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1.fdt"
   [junit4]   2> 64990 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64990 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete pending file _1_Lucene41_0.tim
   [junit4]   2> 64991 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 64991 T142 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-142]: unable to remove file "_1_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 64992 T142 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 64992 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1679451 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
   [junit4]   2> 64992 T146 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 64994 T146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1679451 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
   [junit4]   2> 64994 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _1_Lucene41_0.doc
   [junit4]   2> 64994 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 64994 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _1.fdt
   [junit4]   2> 64995 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_1.fdt"
   [junit4]   2> 64995 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete pending file _1_Lucene41_0.tim
   [junit4]   2> 64995 T146 oasu.LoggingInfoStream.message [IFD][searcherExecutor-58-thread-1]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 64995 T142 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 29
   [junit4]   2> 64999 T144 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2&rows=1} hits=1 status=0 QTime=0 
   [junit4]   2> 65005 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 65005 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 65005 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 65005 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: flush at getReader
   [junit4]   2> 65005 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: qtp20468877-139 startFullFlush
   [junit4]   2> 65006 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 65006 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: qtp20468877-139: flush naked frozen global deletes
   [junit4]   2> 65006 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: push deletes  1 deleted queries bytesUsed=32 delGen=20 packetCount=1 totBytesUsed=32
   [junit4]   2> 65006 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 65007 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: apply all deletes during flush
   [junit4]   2> 65007 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: applyDeletes: infos=[_2(5.0):C1] packetCount=1
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: seg=_2(5.0):C1 segGen=18 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: applyDeletes took 1 msec
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-139]: now checkpoint "_2(5.0):C1/1" [1 segments ; isCommit = false]
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-139]: 0 msec to checkpoint
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: drop 100% deleted segments: _2(5.0):C1/1
   [junit4]   2> 65008 T139 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-139]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 65009 T139 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-139]: 0 msec to checkpoint
   [junit4]   2> 65009 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 65009 T139 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-139]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 65010 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: return reader version=13 reader=StandardDirectoryReader(segments_4:13:nrt)
   [junit4]   2> 65010 T139 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-139]: qtp20468877-139 finishFullFlush success=true
   [junit4]   2> 65010 T139 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-139]: getReader took 5 msec
   [junit4]   2> 65010 T139 C83 oass.SolrIndexSearcher.<init> Opening Searcher@932b3a realtime
   [junit4]   2> 65011 T139 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444214678897033216)} 0 8
   [junit4]   2> 65015 T140 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1444214678909616128), 1 (1444214678909616129)]} 0 0
   [junit4]   2> 65020 T141 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 65020 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: commit: start
   [junit4]   2> 65020 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: commit: enter lock
   [junit4]   2> 65021 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: commit: now prepare
   [junit4]   2> 65021 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: prepareCommit: flush
   [junit4]   2> 65021 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]:   index before flush 
   [junit4]   2> 65022 T141 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-141]: qtp20468877-141 startFullFlush
   [junit4]   2> 65022 T141 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-141]: anyChanges? numDocsInRam=2 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 65022 T141 C83 oasu.LoggingInfoStream.message [DWFC][qtp20468877-141]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 1 deleted terms (unique count=1) bytesUsed=137, segment=_3, aborting=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 11 ]]
   [junit4]   2> 65023 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: flush postings as segment _3 numDocs=2
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: new segment has 0 deleted docs
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: flushedFiles=[_3.fdx, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.fnm, _3_Lucene41_0.tim, _3.fdt]
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: flushed codec=Lucene45
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DWPT][qtp20468877-141]: flushed: segment=_3 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=2,353.706
   [junit4]   2> 65024 T141 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-141]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 65025 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: publishFlushedSegment
   [junit4]   2> 65025 T141 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-141]: push deletes  2 deleted terms (unique count=2) bytesUsed=1024 delGen=22 packetCount=1 totBytesUsed=1024
   [junit4]   2> 65025 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: publish sets newSegment delGen=23 seg=_3(5.0):C2
   [junit4]   2> 65026 T141 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-141]: now checkpoint "_3(5.0):C2" [1 segments ; isCommit = false]
   [junit4]   2> 65026 T141 C83 oasu.LoggingInfoStream.message [IFD][qtp20468877-141]: 0 msec to checkpoint
   [junit4]   2> 65026 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: apply all deletes during flush
   [junit4]   2> 65026 T141 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-141]: applyDeletes: infos=[_3(5.0):C2] packetCount=1
   [junit4]   2> 65027 T141 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-141]: applyDeletes took 1 msec
   [junit4]   2> 65027 T141 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-141]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=24 packetCount=1
   [junit4]   2> 65027 T141 C83 oasu.LoggingInfoStream.message [BD][qtp20468877-141]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 65027 T141 C83 oasu.LoggingInfoStream.message [DW][qtp20468877-141]: qtp20468877-141 finishFullFlush success=true
   [junit4]   2> 65027 T141 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-141]: findMerges: 1 segments
   [junit4]   2> 65028 T141 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-141]:   seg=_3(5.0):C2 size=0.001 MB [floored]
   [junit4]   2> 65028 T141 C83 oasu.LoggingInfoStream.message [TMP][qtp20468877-141]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 65029 T141 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-141]: now merge
   [junit4]   2> 65029 T141 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-141]:   index: _3(5.0):C2
   [junit4]   2> 65029 T141 C83 oasu.LoggingInfoStream.message [CMS][qtp20468877-141]:   no more merges pending; now return
   [junit4]   2> 65030 T141 C83 oasu.LoggingInfoStream.message [IW][qtp20468877-141]: startCommit(): start
   [junit4]   2> 65030 T141 C83 oasu

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

sc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=10 status=0 QTime=0 
   [junit4]   2> 272618 T135 oas.SolrTestCaseJ4.tearDown ###Ending testContentStreamRequest
   [junit4]   2> 272634 T135 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=29910895
   [junit4]   2> 272635 T135 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@2ab50f
   [junit4]   2> 272709 T135 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=58,autocommit maxTime=15000ms,autocommits=1,soft autocommits=3,optimizes=2,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=1,cumulative_adds=133,cumulative_deletesById=5,cumulative_deletesByQuery=27,cumulative_errors=1}
   [junit4]   2> 272711 T135 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 272711 T135 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 272711 T135 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 272712 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: now flush at close waitForMerges=true
   [junit4]   2> 272712 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   start flush: applyAllDeletes=true
   [junit4]   2> 272712 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   index before flush _12(5.0):C10
   [junit4]   2> 272713 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker startFullFlush
   [junit4]   2> 272713 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 272714 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker finishFullFlush success=true
   [junit4]   2> 272714 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: apply all deletes during flush
   [junit4]   2> 272715 T135 C105 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 272715 T135 C105 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=226 packetCount=0
   [junit4]   2> 272716 T135 C105 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: now merge
   [junit4]   2> 272716 T135 C105 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   index: _12(5.0):C10
   [junit4]   2> 272717 T135 C105 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   no more merges pending; now return
   [junit4]   2> 272718 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: waitForMerges
   [junit4]   2> 272718 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: waitForMerges done
   [junit4]   2> 272719 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: now call final commit()
   [junit4]   2> 272719 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: commit: start
   [junit4]   2> 272719 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: commit: enter lock
   [junit4]   2> 272720 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: commit: now prepare
   [junit4]   2> 272720 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: prepareCommit: flush
   [junit4]   2> 272720 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   index before flush _12(5.0):C10
   [junit4]   2> 272721 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker startFullFlush
   [junit4]   2> 272721 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 272721 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: apply all deletes during flush
   [junit4]   2> 272722 T135 C105 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 272722 T135 C105 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@aadc72 minGen=226 packetCount=0
   [junit4]   2> 272722 T135 C105 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker finishFullFlush success=true
   [junit4]   2> 272722 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: startCommit(): start
   [junit4]   2> 272724 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]:   skip startCommit(): no changes pending
   [junit4]   2> 272724 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: commit: pendingCommit == null; skip
   [junit4]   2> 272725 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: commit: done
   [junit4]   2> 272725 T135 C105 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[CA21D1B8D2B0BFDC]-worker]: at close: _12(5.0):C10
   [junit4]   2> 272730 T135 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 272731 T135 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 272731 T135 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index;done=false>>]
   [junit4]   2> 272732 T135 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\index
   [junit4]   2> 272732 T135 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\ [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\;done=false>>]
   [junit4]   2> 272732 T135 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-solrj\test\J0\solrtest-SolrExampleJettyTest-1377310444824\
   [junit4]   2> 272733 T135 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 272787 T135 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=Lucene45: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=en_IN, timezone=CNT
   [junit4]   2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_25 (32-bit)/cpus=2,threads=1,free=3439696,total=39813120
   [junit4]   2> NOTE: All tests run in this JVM: [TestBatchUpdate, SolrExampleXMLTest, TestDocumentObjectBinder, JettyWebappTest, SolrExampleStreamingBinaryTest, MultiCoreExampleJettyTest, SolrExampleJettyTest]
   [junit4] Completed in 209.68s, 27 tests, 1 error <<< FAILURES!

[...truncated 125 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:389: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:369: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:194: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:450: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1230: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:873: There were test failures: 46 suites, 272 tests, 1 error, 1 ignored (1 assumption)

Total time: 90 minutes 57 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -server -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure