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/05 07:15:42 UTC

[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 688 - Failure!

Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/688/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseG1GC

1 tests failed.
REGRESSION:  org.apache.solr.client.solrj.embedded.SolrExampleStreamingBinaryTest.testPivotFacets

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

Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:53768/solr/collection1
	at __randomizedtesting.SeedInfo.seed([619FEC580107CFFD:DF590C93D52056B3]: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.impl.ConcurrentUpdateSolrServer.request(ConcurrentUpdateSolrServer.java:256)
	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.SolrServer.commit(SolrServer.java:146)
	at org.apache.solr.client.solrj.SolrExampleTests.doPivotFacetTest(SolrExampleTests.java:1002)
	at org.apache.solr.client.solrj.SolrExampleTests.testPivotFacets(SolrExampleTests.java:990)
	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)
	... 47 more




Build Log:
[...truncated 10801 lines...]
   [junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleStreamingBinaryTest
   [junit4]   2> 66035 T97 oas.SolrTestCaseJ4.startTrackingSearchers WARN startTrackingSearchers: numOpens=7 numCloses=7
   [junit4]   2> 66036 T97 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
   [junit4]   2> 66037 T97 oas.SolrTestCaseJ4.initCore ####initCore
   [junit4]   2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleStreamingBinaryTest-1375679224393
   [junit4]   2> 66039 T97 oas.SolrTestCaseJ4.initCore ####initCore end
   [junit4]   2> 66095 T97 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 66732 T97 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
   [junit4]   2> 66750 T97 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:53768
   [junit4]   2> 66753 T97 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 66776 T97 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 66777 T97 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
   [junit4]   2> 66778 T97 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/'
   [junit4]   2> 66907 T97 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/solr.xml
   [junit4]   2> 67188 T97 oasc.ConfigSolrXml.<init> Config-defined core root directory: 
   [junit4]   2> 67189 T97 oasc.CoreContainer.<init> New CoreContainer 1003797945
   [junit4]   2> 67190 T97 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/]
   [junit4]   2> 67195 T97 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
   [junit4]   2> 67197 T97 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 67197 T97 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
   [junit4]   2> 67198 T97 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 67199 T97 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 67200 T97 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 67201 T97 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 67202 T97 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 67203 T97 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 67204 T97 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
   [junit4]   2> 67223 T97 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
   [junit4]   2> 67266 T97 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/
   [junit4]   2> 67279 T97 oasc.CorePropertiesLocator.discover Found 1 core definitions
   [junit4]   2> 67288 T107 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1
   [junit4]   2> 67289 T107 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/'
   [junit4]   2> 67478 T107 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
   [junit4]   2> 67479 T107 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
   [junit4]   2> 67480 T107 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 67481 T107 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
   [junit4]   2> 67481 T107 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 67482 T107 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
   [junit4]   2> 67483 T107 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 67484 T107 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
   [junit4]   2> 67484 T107 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 67579 T107 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
   [junit4]   2> 67648 T107 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
   [junit4]   2> 67814 T107 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 67815 T107 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 67937 T107 oass.IndexSchema.readSchema [collection1] Schema name=example
   [junit4]   2> 69816 T107 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 69903 T107 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 69920 T107 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 70210 T107 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 70211 T107 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/
   [junit4]   2> 70212 T107 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6a628568
   [junit4]   2> 70248 T107 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
   [junit4]   2> 70249 T107 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
   [junit4]   2> 70250 T107 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393
   [junit4]   2> 70251 T107 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index/
   [junit4]   2> 70251 T107 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index' doesn't exist. Creating new index...
   [junit4]   2> 70252 T107 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index
   [junit4]   2> 70255 T107 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-92-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@76fe1a35
   [junit4]   2> 70255 T107 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-92-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 70256 T107 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-92-thread-1]: 0 msec to checkpoint
   [junit4]   2> 70256 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: init: create=true
   [junit4]   2> 70257 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd)
   [junit4]   2> 	index=
   [junit4]   2> 	version=4.5-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_45
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	readerTermsIndexDivisor=1
   [junit4]   2> 	termIndexInterval=32
   [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=Lucene42
   [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@246aca9b
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 70257 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: now flush at close waitForMerges=true
   [junit4]   2> 70258 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]:   start flush: applyAllDeletes=true
   [junit4]   2> 70258 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]:   index before flush 
   [junit4]   2> 70259 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: coreLoadExecutor-92-thread-1 startFullFlush
   [junit4]   2> 70259 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 70260 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: coreLoadExecutor-92-thread-1 finishFullFlush success=true
   [junit4]   2> 70260 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: apply all deletes during flush
   [junit4]   2> 70261 T107 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-92-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@5f1b98ca minGen=9223372036854775807 packetCount=0
   [junit4]   2> 70261 T107 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-92-thread-1]: now merge
   [junit4]   2> 70263 T107 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-92-thread-1]:   index: 
   [junit4]   2> 70265 T107 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-92-thread-1]:   no more merges pending; now return
   [junit4]   2> 70266 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: waitForMerges
   [junit4]   2> 70266 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: waitForMerges done
   [junit4]   2> 70267 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: now call final commit()
   [junit4]   2> 70267 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: start
   [junit4]   2> 70268 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: enter lock
   [junit4]   2> 70268 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: now prepare
   [junit4]   2> 70269 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: prepareCommit: flush
   [junit4]   2> 70269 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]:   index before flush 
   [junit4]   2> 70270 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: coreLoadExecutor-92-thread-1 startFullFlush
   [junit4]   2> 70271 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 70271 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: apply all deletes during flush
   [junit4]   2> 70272 T107 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-92-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@5f1b98ca minGen=9223372036854775807 packetCount=0
   [junit4]   2> 70273 T107 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-92-thread-1]: coreLoadExecutor-92-thread-1 finishFullFlush success=true
   [junit4]   2> 70273 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: startCommit(): start
   [junit4]   2> 70274 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: startCommit index= changeCount=1
   [junit4]   2> 70276 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: done all syncs: []
   [junit4]   2> 70276 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: pendingCommit != null
   [junit4]   2> 70277 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: wrote segments file "segments_1"
   [junit4]   2> 70278 T107 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-92-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
   [junit4]   2> 70278 T107 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_1,generation=1}
   [junit4]   2> 70279 T107 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 70280 T107 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-92-thread-1]: 2 msec to checkpoint
   [junit4]   2> 70281 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: commit: done
   [junit4]   2> 70281 T107 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-92-thread-1]: at close: 
   [junit4]   2> 70284 T107 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
   [junit4]   2> 70285 T107 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
   [junit4]   2> 70286 T107 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
   [junit4]   2> 70286 T107 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
   [junit4]   2> 70287 T107 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
   [junit4]   2> 70318 T107 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
   [junit4]   2> 70320 T107 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
   [junit4]   2> 70322 T107 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 70323 T107 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
   [junit4]   2> 70325 T107 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 70327 T107 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
   [junit4]   2> 70328 T107 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
   [junit4]   2> 70329 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 70330 T107 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 70330 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
   [junit4]   2> 70331 T107 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
   [junit4]   2> 70331 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 70332 T107 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 70333 T107 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
   [junit4]   2> 70334 T107 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
   [junit4]   2> 70341 T107 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
   [junit4]   2> 70343 T107 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 70344 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 70344 T107 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
   [junit4]   2> 70345 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 70345 T107 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
   [junit4]   2> 70346 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 70346 T107 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
   [junit4]   2> 70347 T107 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 70354 T107 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
   [junit4]   2> 70377 T107 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 70380 T107 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 70383 T107 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 70430 T107 oass.SolrIndexSearcher.<init> Opening Searcher@4c885344 main
   [junit4]   2> 70433 T107 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms; 
   [junit4]   2> 70434 T107 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 70437 T107 oashc.SpellCheckComponent.inform Initializing spell checkers
   [junit4]   2> 70438 T107 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> 70439 T107 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
   [junit4]   2> 70442 T107 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/conf/elevate.xml
   [junit4]   2> 70512 T107 oash.ReplicationHandler.inform Commits will be reserved for  10000
   [junit4]   2> 70527 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@4c885344 main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> ASYNC  NEW_CORE C14 name=collection1 org.apache.solr.core.SolrCore@3f3c92ad
   [junit4]   2> 70531 T108 C14 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=4 
   [junit4]   2> 70532 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 70534 T108 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
   [junit4]   2> 70538 T108 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
   [junit4]   2> 70545 T108 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4c885344 main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> 70558 T107 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 70560 T97 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0
   [junit4]   2> 70561 T97 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 70562 T97 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#53768
   [junit4]   2> 70579 T97 oas.SolrTestCaseJ4.setUp ###Starting testChineseDefaults
   [junit4]   2> 70586 T97 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 71005 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@76fe1a35
   [junit4]   2> 71006 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: init: load commit "segments_1"
   [junit4]   2> 71007 T102 C14 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_1,generation=1}
   [junit4]   2> 71008 T102 C14 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 71008 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 71009 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 0 msec to checkpoint
   [junit4]   2> 71009 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: init: create=false
   [junit4]   2> 71010 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd)
   [junit4]   2> 	index=
   [junit4]   2> 	version=4.5-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_45
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	readerTermsIndexDivisor=1
   [junit4]   2> 	termIndexInterval=32
   [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=Lucene42
   [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@3f10d98a
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 71012 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: flush at getReader
   [junit4]   2> 71013 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 startFullFlush
   [junit4]   2> 71014 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71016 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102: flush naked frozen global deletes
   [junit4]   2> 71016 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: push deletes  1 deleted queries bytesUsed=32 delGen=1 packetCount=1 totBytesUsed=32
   [junit4]   2> 71017 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 71018 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: apply all deletes during flush
   [junit4]   2> 71018 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=9223372036854775807 packetCount=1
   [junit4]   2> 71019 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71019 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
   [junit4]   2> 71020 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 finishFullFlush success=true
   [junit4]   2> 71020 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: getReader took 8 msec
   [junit4]   2> 71021 T102 C14 oass.SolrIndexSearcher.<init> Opening Searcher@499fdc26 realtime
   [junit4]   2> 71023 T102 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1442504223601197056)} 0 32
   [junit4]   2> 71034 T103 C14 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 71035 T103 C14 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
   [junit4]   2> 71036 T103 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-103]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71036 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
   [junit4]   2> 71037 T103 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-103]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71037 T103 C14 oass.SolrIndexSearcher.<init> Opening Searcher@c56e087 main
   [junit4]   2> 71038 T103 C14 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 71039 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@c56e087 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 71040 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 71049 T108 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c56e087 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 71051 T103 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 18
   [junit4]   2> 71061 T104 C14 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 
   [junit4]   2> 71064 T97 oascsi.ConcurrentUpdateSolrServer.request blocking for commit/optimize
   [junit4]   2> 71073 T105 C14 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 71076 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: start
   [junit4]   2> 71080 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: enter lock
   [junit4]   2> 71082 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: now prepare
   [junit4]   2> 71083 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: prepareCommit: flush
   [junit4]   2> 71083 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]:   index before flush 
   [junit4]   2> 71084 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: qtp1845849350-105 startFullFlush
   [junit4]   2> 71085 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71086 T105 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-105]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 1 ]]
   [junit4]   2> 71087 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: flush postings as segment _0 numDocs=1
   [junit4]   2> 71091 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: new segment has 0 deleted docs
   [junit4]   2> 71091 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: new segment has no vectors; norms; no docValues; prox; freqs
   [junit4]   2> 71092 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: 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> 71092 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: flushed codec=Lucene42
   [junit4]   2> 71093 T105 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-105]: flushed: segment=_0 ramUsed=0.071 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,230.723
   [junit4]   2> 71094 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 71095 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: publishFlushedSegment
   [junit4]   2> 71096 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: push deletes  1 deleted terms (unique count=1) bytesUsed=1024 delGen=3 packetCount=1 totBytesUsed=1024
   [junit4]   2> 71097 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: publish sets newSegment delGen=4 seg=_0(4.5):C1
   [junit4]   2> 71097 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = false]
   [junit4]   2> 71098 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: 0 msec to checkpoint
   [junit4]   2> 71098 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: apply all deletes during flush
   [junit4]   2> 71101 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
   [junit4]   2> 71101 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: applyDeletes took 0 msec
   [junit4]   2> 71102 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=5 packetCount=1
   [junit4]   2> 71103 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71103 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: qtp1845849350-105 finishFullFlush success=true
   [junit4]   2> 71104 T105 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-105]: findMerges: 1 segments
   [junit4]   2> 71105 T105 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-105]:   seg=_0(4.5):C1 size=0.001 MB [floored]
   [junit4]   2> 71105 T105 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-105]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 71106 T105 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-105]: now merge
   [junit4]   2> 71106 T105 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-105]:   index: _0(4.5):C1
   [junit4]   2> 71107 T105 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-105]:   no more merges pending; now return
   [junit4]   2> 71107 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: startCommit(): start
   [junit4]   2> 71108 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: startCommit index=_0(4.5):C1 changeCount=3
   [junit4]   2> 71109 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: 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> 71109 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: pendingCommit != null
   [junit4]   2> 71110 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: wrote segments file "segments_2"
   [junit4]   2> 71110 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = true]
   [junit4]   2> 71111 T105 C14 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_1,generation=1}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_2,generation=2}
   [junit4]   2> 71112 T105 C14 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
   [junit4]   2> 71112 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: deleteCommits: now decRef commit "segments_1"
   [junit4]   2> 71113 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: delete "segments_1"
   [junit4]   2> 71113 T105 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-105]: 2 msec to checkpoint
   [junit4]   2> 71114 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: commit: done
   [junit4]   2> 71114 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71115 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 71116 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: flush at getReader
   [junit4]   2> 71116 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: qtp1845849350-105 startFullFlush
   [junit4]   2> 71117 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71117 T105 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-105]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 2 ]]
   [junit4]   2> 71118 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: apply all deletes during flush
   [junit4]   2> 71118 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: applyDeletes: no deletes; skipping
   [junit4]   2> 71119 T105 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-105]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=5 packetCount=0
   [junit4]   2> 71121 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)
   [junit4]   2> 71122 T105 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-105]: qtp1845849350-105 finishFullFlush success=true
   [junit4]   2> 71127 T105 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-105]: getReader took 11 msec
   [junit4]   2> 71128 T105 C14 oass.SolrIndexSearcher.<init> Opening Searcher@277ee847 main
   [junit4]   2> 71129 T105 C14 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 71129 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@277ee847 main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
   [junit4]   2> 71130 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 71141 T108 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@277ee847 main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
   [junit4]   2> 71146 T105 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {add=[42 (1442504223673548800)],commit=} 0 77
   [junit4]   2> 71165 T106 C14 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=????&wt=javabin&version=2} hits=1 status=0 QTime=3 
   [junit4]   2> 71169 T97 oas.SolrTestCaseJ4.tearDown ###Ending testChineseDefaults
   [junit4]   2> 71189 T97 oas.SolrTestCaseJ4.setUp ###Starting testUnicode
   [junit4]   2> 71196 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71197 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 71197 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71198 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: flush at getReader
   [junit4]   2> 71198 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: qtp1845849350-100 startFullFlush
   [junit4]   2> 71199 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71202 T100 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-100]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 3 ]]
   [junit4]   2> 71209 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: qtp1845849350-100: flush naked frozen global deletes
   [junit4]   2> 71210 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: push deletes  1 deleted queries bytesUsed=32 delGen=7 packetCount=1 totBytesUsed=32
   [junit4]   2> 71211 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 71211 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: apply all deletes during flush
   [junit4]   2> 71212 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
   [junit4]   2> 71213 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: seg=_0(4.5):C1 segGen=5 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
   [junit4]   2> 71214 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: applyDeletes took 2 msec
   [junit4]   2> 71215 T100 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-100]: now checkpoint "_0(4.5):C1/1" [1 segments ; isCommit = false]
   [junit4]   2> 71215 T100 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-100]: 0 msec to checkpoint
   [junit4]   2> 71216 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: drop 100% deleted segments: _0(4.5):C1/1
   [junit4]   2> 71216 T100 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-100]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 71217 T100 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-100]: 0 msec to checkpoint
   [junit4]   2> 71217 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=9223372036854775807 packetCount=1
   [junit4]   2> 71218 T100 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-100]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71219 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
   [junit4]   2> 71219 T100 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-100]: qtp1845849350-100 finishFullFlush success=true
   [junit4]   2> 71220 T100 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-100]: getReader took 22 msec
   [junit4]   2> 71220 T100 C14 oass.SolrIndexSearcher.<init> Opening Searcher@1a00a506 realtime
   [junit4]   2> 71221 T100 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1442504223803572224)} 0 27
   [junit4]   2> 71252 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@1f36154e
   [junit4]   2> 71539 T102 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1442504223893749760), 1 (1442504223895846912), 2 (1442504223895846913), 3 (1442504223896895488), 4 (1442504223897944064)]} 0 259
   [junit4]   2> 71542 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 is 200
   [junit4]   2> 71544 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@1f36154e
   [junit4]   2> 71549 T104 C14 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 71549 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: start
   [junit4]   2> 71550 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: enter lock
   [junit4]   2> 71550 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: now prepare
   [junit4]   2> 71551 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: prepareCommit: flush
   [junit4]   2> 71552 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]:   index before flush 
   [junit4]   2> 71553 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: qtp1845849350-104 startFullFlush
   [junit4]   2> 71554 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: anyChanges? numDocsInRam=5 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71554 T104 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-104]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 4 deleted terms (unique count=4) bytesUsed=660, segment=_1, aborting=false, numDocsInRAM=5, deleteQueue=DWDQ: [ generation: 4 ]]
   [junit4]   2> 71557 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: flush postings as segment _1 numDocs=5
   [junit4]   2> 71564 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: new segment has 0 deleted docs
   [junit4]   2> 71565 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 71566 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: flushedFiles=[_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
   [junit4]   2> 71567 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: flushed codec=Lucene42
   [junit4]   2> 71568 T104 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-104]: flushed: segment=_1 ramUsed=0.064 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=4,283.399
   [junit4]   2> 71569 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 71570 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: publishFlushedSegment
   [junit4]   2> 71571 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: push deletes  5 deleted terms (unique count=5) bytesUsed=1024 delGen=9 packetCount=1 totBytesUsed=1024
   [junit4]   2> 71572 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: publish sets newSegment delGen=10 seg=_1(4.5):C5
   [junit4]   2> 71572 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: now checkpoint "_1(4.5):C5" [1 segments ; isCommit = false]
   [junit4]   2> 71572 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 0 msec to checkpoint
   [junit4]   2> 71573 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: apply all deletes during flush
   [junit4]   2> 71573 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: applyDeletes: infos=[_1(4.5):C5] packetCount=1
   [junit4]   2> 71573 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: applyDeletes took 0 msec
   [junit4]   2> 71574 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=11 packetCount=1
   [junit4]   2> 71574 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71574 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: qtp1845849350-104 finishFullFlush success=true
   [junit4]   2> 71575 T104 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-104]: findMerges: 1 segments
   [junit4]   2> 71575 T104 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-104]:   seg=_1(4.5):C5 size=0.001 MB [floored]
   [junit4]   2> 71576 T104 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-104]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 71576 T104 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-104]: now merge
   [junit4]   2> 71577 T104 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-104]:   index: _1(4.5):C5
   [junit4]   2> 71577 T104 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-104]:   no more merges pending; now return
   [junit4]   2> 71578 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: startCommit(): start
   [junit4]   2> 71578 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: startCommit index=_1(4.5):C5 changeCount=8
   [junit4]   2> 71579 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: 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> 71579 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: pendingCommit != null
   [junit4]   2> 71580 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: wrote segments file "segments_3"
   [junit4]   2> 71581 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: now checkpoint "_1(4.5):C5" [1 segments ; isCommit = true]
   [junit4]   2> 71581 T104 C14 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_3,generation=3}
   [junit4]   2> 71582 T104 C14 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
   [junit4]   2> 71582 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: deleteCommits: now decRef commit "segments_2"
   [junit4]   2> 71582 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.fnm"
   [junit4]   2> 71583 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 71583 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71583 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 71584 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71584 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.nvd"
   [junit4]   2> 71585 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 71585 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "segments_2"
   [junit4]   2> 71585 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.fdx"
   [junit4]   2> 71586 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.si"
   [junit4]   2> 71586 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.nvm"
   [junit4]   2> 71587 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 71587 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71587 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.fdt"
   [junit4]   2> 71588 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 71588 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.tip"
   [junit4]   2> 71588 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 7 msec to checkpoint
   [junit4]   2> 71589 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: commit: done
   [junit4]   2> 71589 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71589 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 71590 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: flush at getReader
   [junit4]   2> 71590 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: qtp1845849350-104 startFullFlush
   [junit4]   2> 71591 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71591 T104 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-104]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 5 ]]
   [junit4]   2> 71591 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: apply all deletes during flush
   [junit4]   2> 71592 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: applyDeletes: no deletes; skipping
   [junit4]   2> 71592 T104 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-104]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=11 packetCount=0
   [junit4]   2> 71593 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(4.5):C5)
   [junit4]   2> 71594 T104 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-104]: qtp1845849350-104 finishFullFlush success=true
   [junit4]   2> 71594 T104 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-104]: getReader took 4 msec
   [junit4]   2> 71595 T104 C14 oass.SolrIndexSearcher.<init> Opening Searcher@462619c6 main
   [junit4]   2> 71595 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 71595 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 71596 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71596 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 71597 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 71597 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71597 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete pending file _0.nvd
   [junit4]   2> 71599 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.nvd"
   [junit4]   2> 71599 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 71599 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 71600 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 71600 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: 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> 71600 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete pending file _0.fdt
   [junit4]   2> 71601 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: delete "_0.fdt"
   [junit4]   2> 71601 T104 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-104]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 71602 T104 C14 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 71604 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@462619c6 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C5)}
   [junit4]   2> 71607 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 71617 T108 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@462619c6 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C5)}
   [junit4]   2> 71621 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 71622 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 71622 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 71622 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 71623 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _0.nvd
   [junit4]   2> 71623 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_0.nvd"
   [junit4]   2> 71623 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 71624 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 71624 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _0.fdt
   [junit4]   2> 71625 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_0.fdt"
   [junit4]   2> 71625 T104 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 77
   [junit4]   2> 71634 T105 C14 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2&rows=5} hits=5 status=0 QTime=1 
   [junit4]   2> 71668 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71673 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 71675 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71676 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: flush at getReader
   [junit4]   2> 71676 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106 startFullFlush
   [junit4]   2> 71677 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71677 T106 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-106]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 6 ]]
   [junit4]   2> 71678 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106: flush naked frozen global deletes
   [junit4]   2> 71681 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: push deletes  1 deleted queries bytesUsed=32 delGen=13 packetCount=1 totBytesUsed=32
   [junit4]   2> 71682 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 71682 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: apply all deletes during flush
   [junit4]   2> 71683 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: applyDeletes: infos=[_1(4.5):C5] packetCount=1
   [junit4]   2> 71684 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: seg=_1(4.5):C5 segGen=11 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=5 100% deleted
   [junit4]   2> 71685 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: applyDeletes took 2 msec
   [junit4]   2> 71686 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: now checkpoint "_1(4.5):C5/5" [1 segments ; isCommit = false]
   [junit4]   2> 71687 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: 0 msec to checkpoint
   [junit4]   2> 71687 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: drop 100% deleted segments: _1(4.5):C5/5
   [junit4]   2> 71688 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 71692 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: 4 msec to checkpoint
   [junit4]   2> 71693 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=9223372036854775807 packetCount=1
   [junit4]   2> 71693 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71694 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
   [junit4]   2> 71694 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106 finishFullFlush success=true
   [junit4]   2> 71694 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: getReader took 18 msec
   [junit4]   2> 71695 T106 C14 oass.SolrIndexSearcher.<init> Opening Searcher@80b1d65 realtime
   [junit4]   2> 71695 T106 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1442504224298500096)} 0 30
   [junit4]   2> 71700 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@11b6d603
   [junit4]   2> 71960 T103 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1442504224343588864), 1 (1442504224345686016)]} 0 252
   [junit4]   2> 71965 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 is 200
   [junit4]   2> 71966 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@11b6d603
   [junit4]   2> 71971 T102 C14 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 71972 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: start
   [junit4]   2> 71972 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: enter lock
   [junit4]   2> 71973 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: now prepare
   [junit4]   2> 71973 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: prepareCommit: flush
   [junit4]   2> 71974 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]:   index before flush 
   [junit4]   2> 71974 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 startFullFlush
   [junit4]   2> 71975 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: anyChanges? numDocsInRam=2 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 71976 T102 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-102]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 1 deleted terms (unique count=1) bytesUsed=165, segment=_2, aborting=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 7 ]]
   [junit4]   2> 71977 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: flush postings as segment _2 numDocs=2
   [junit4]   2> 71981 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: new segment has 0 deleted docs
   [junit4]   2> 71982 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 71982 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: flushedFiles=[_2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
   [junit4]   2> 71983 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: flushed codec=Lucene42
   [junit4]   2> 71983 T102 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-102]: flushed: segment=_2 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=2,377.723
   [junit4]   2> 71984 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 71985 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: publishFlushedSegment
   [junit4]   2> 71985 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: push deletes  2 deleted terms (unique count=2) bytesUsed=1024 delGen=15 packetCount=1 totBytesUsed=1024
   [junit4]   2> 71986 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: publish sets newSegment delGen=16 seg=_2(4.5):C2
   [junit4]   2> 71986 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: now checkpoint "_2(4.5):C2" [1 segments ; isCommit = false]
   [junit4]   2> 71987 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 0 msec to checkpoint
   [junit4]   2> 71988 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: apply all deletes during flush
   [junit4]   2> 71989 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: applyDeletes: infos=[_2(4.5):C2] packetCount=1
   [junit4]   2> 71990 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: applyDeletes took 1 msec
   [junit4]   2> 71990 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=17 packetCount=1
   [junit4]   2> 71991 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 71991 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 finishFullFlush success=true
   [junit4]   2> 71992 T102 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-102]: findMerges: 1 segments
   [junit4]   2> 71993 T102 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-102]:   seg=_2(4.5):C2 size=0.001 MB [floored]
   [junit4]   2> 71993 T102 C14 oasu.LoggingInfoStream.message [TMP][qtp1845849350-102]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 71994 T102 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-102]: now merge
   [junit4]   2> 71994 T102 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-102]:   index: _2(4.5):C2
   [junit4]   2> 71995 T102 C14 oasu.LoggingInfoStream.message [CMS][qtp1845849350-102]:   no more merges pending; now return
   [junit4]   2> 71995 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: startCommit(): start
   [junit4]   2> 71996 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: startCommit index=_2(4.5):C2 changeCount=13
   [junit4]   2> 71997 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: 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> 71997 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: pendingCommit != null
   [junit4]   2> 71998 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: wrote segments file "segments_4"
   [junit4]   2> 71999 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: now checkpoint "_2(4.5):C2" [1 segments ; isCommit = true]
   [junit4]   2> 72000 T102 C14 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538330b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d4419bd),segFN=segments_4,generation=4}
   [junit4]   2> 72000 T102 C14 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
   [junit4]   2> 72001 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: deleteCommits: now decRef commit "segments_3"
   [junit4]   2> 72001 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1.fdx"
   [junit4]   2> 72002 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 72002 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 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> 72003 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1.fdt"
   [junit4]   2> 72004 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 72004 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1.si"
   [junit4]   2> 72005 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 72005 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 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> 72006 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1_Lucene41_0.tip"
   [junit4]   2> 72006 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1.fnm"
   [junit4]   2> 72007 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "segments_3"
   [junit4]   2> 72008 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 8 msec to checkpoint
   [junit4]   2> 72008 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: commit: done
   [junit4]   2> 72009 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72010 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 72010 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: flush at getReader
   [junit4]   2> 72010 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 startFullFlush
   [junit4]   2> 72011 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72012 T102 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-102]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 8 ]]
   [junit4]   2> 72012 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: apply all deletes during flush
   [junit4]   2> 72013 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: applyDeletes: no deletes; skipping
   [junit4]   2> 72013 T102 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-102]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=17 packetCount=0
   [junit4]   2> 72015 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: return reader version=11 reader=StandardDirectoryReader(segments_4:11:nrt _2(4.5):C2)
   [junit4]   2> 72016 T102 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-102]: qtp1845849350-102 finishFullFlush success=true
   [junit4]   2> 72016 T102 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-102]: getReader took 6 msec
   [junit4]   2> 72017 T102 C14 oass.SolrIndexSearcher.<init> Opening Searcher@5c3301f3 main
   [junit4]   2> 72018 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete pending file _1_Lucene41_0.doc
   [junit4]   2> 72019 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 72019 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 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> 72020 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete pending file _1.fdt
   [junit4]   2> 72020 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1.fdt"
   [junit4]   2> 72021 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 72021 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete pending file _1_Lucene41_0.tim
   [junit4]   2> 72022 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 72022 T102 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-102]: 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> 72023 T102 C14 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 72024 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@5c3301f3 main{StandardDirectoryReader(segments_4:11:nrt _2(4.5):C2)}
   [junit4]   2> 72025 T108 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 72049 T108 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c3301f3 main{StandardDirectoryReader(segments_4:11:nrt _2(4.5):C2)}
   [junit4]   2> 72051 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _1_Lucene41_0.doc
   [junit4]   2> 72051 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 72065 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _1.fdt
   [junit4]   2> 72067 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_1.fdt"
   [junit4]   2> 72088 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete pending file _1_Lucene41_0.tim
   [junit4]   2> 72088 T108 oasu.LoggingInfoStream.message [IFD][searcherExecutor-93-thread-1]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 72089 T102 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 118
   [junit4]   2> 72114 T102 C14 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2&rows=2} hits=2 status=0 QTime=3 
   [junit4]   2> 72133 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72134 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 72135 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72136 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: flush at getReader
   [junit4]   2> 72136 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106 startFullFlush
   [junit4]   2> 72137 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72138 T106 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-106]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 9 ]]
   [junit4]   2> 72138 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106: flush naked frozen global deletes
   [junit4]   2> 72139 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: push deletes  1 deleted queries bytesUsed=32 delGen=19 packetCount=1 totBytesUsed=32
   [junit4]   2> 72148 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 72149 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: apply all deletes during flush
   [junit4]   2> 72150 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: applyDeletes: infos=[_2(4.5):C2] packetCount=1
   [junit4]   2> 72151 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: seg=_2(4.5):C2 segGen=17 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=2 100% deleted
   [junit4]   2> 72151 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: applyDeletes took 1 msec
   [junit4]   2> 72152 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: now checkpoint "_2(4.5):C2/2" [1 segments ; isCommit = false]
   [junit4]   2> 72153 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: 0 msec to checkpoint
   [junit4]   2> 72153 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: drop 100% deleted segments: _2(4.5):C2/2
   [junit4]   2> 72154 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 72154 T106 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-106]: 0 msec to checkpoint
   [junit4]   2> 72155 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=9223372036854775807 packetCount=1
   [junit4]   2> 72161 T106 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-106]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 72161 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: return reader version=13 reader=StandardDirectoryReader(segments_4:13:nrt)
   [junit4]   2> 72162 T106 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-106]: qtp1845849350-106 finishFullFlush success=true
   [junit4]   2> 72162 T106 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-106]: getReader took 26 msec
   [junit4]   2> 72163 T106 C14 oass.SolrIndexSearcher.<init> Opening Searcher@64ed9b24 realtime
   [junit4]   2> 72163 T106 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1442504224786087936)} 0 32
   [junit4]   2> 72168 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@2b648c40
   [junit4]   2> 72425 T100 C14 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0 (1442504224832225280), 1 (1442504224834322432), 2 (1442504224836419584), 3 (1442504224842711040), 4 (1442504224843759616)]} 0 250
   [junit4]   2> 72438 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 is 200
   [junit4]   2> 72440 T111 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@2b648c40
   [junit4]   2> 72445 T103 C14 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 72446 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: commit: start
   [junit4]   2> 72447 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: commit: enter lock
   [junit4]   2> 72447 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: commit: now prepare
   [junit4]   2> 72448 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: prepareCommit: flush
   [junit4]   2> 72448 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]:   index before flush 
   [junit4]   2> 72449 T103 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-103]: qtp1845849350-103 startFullFlush
   [junit4]   2> 72449 T103 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-103]: anyChanges? numDocsInRam=5 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 72450 T103 C14 oasu.LoggingInfoStream.message [DWFC][qtp1845849350-103]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 4 deleted terms (unique count=4) bytesUsed=660, segment=_3, aborting=false, numDocsInRAM=5, deleteQueue=DWDQ: [ generation: 10 ]]
   [junit4]   2> 72451 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: flush postings as segment _3 numDocs=5
   [junit4]   2> 72458 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: new segment has 0 deleted docs
   [junit4]   2> 72459 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 72459 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: flushedFiles=[_3.fdx, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.fnm, _3_Lucene41_0.tim, _3.fdt]
   [junit4]   2> 72460 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: flushed codec=Lucene42
   [junit4]   2> 72461 T103 C14 oasu.LoggingInfoStream.message [DWPT][qtp1845849350-103]: flushed: segment=_3 ramUsed=0.064 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=4,969.555
   [junit4]   2> 72462 T103 C14 oasu.LoggingInfoStream.message [DW][qtp1845849350-103]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 72462 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: publishFlushedSegment
   [junit4]   2> 72463 T103 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-103]: push deletes  5 deleted terms (unique count=5) bytesUsed=1024 delGen=21 packetCount=1 totBytesUsed=1024
   [junit4]   2> 72463 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: publish sets newSegment delGen=22 seg=_3(4.5):C5
   [junit4]   2> 72464 T103 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-103]: now checkpoint "_3(4.5):C5" [1 segments ; isCommit = false]
   [junit4]   2> 72464 T103 C14 oasu.LoggingInfoStream.message [IFD][qtp1845849350-103]: 0 msec to checkpoint
   [junit4]   2> 72465 T103 C14 oasu.LoggingInfoStream.message [IW][qtp1845849350-103]: apply all deletes during flush
   [junit4]   2> 72465 T103 C14 oasu.LoggingInfoStream.message [BD][qtp1845849350-103]: applyDelet

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

olrCoreState Closing SolrCoreState
   [junit4]   2> 298154 T97 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 298155 T97 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> 298169 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: now flush at close waitForMerges=true
   [junit4]   2> 298170 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   start flush: applyAllDeletes=true
   [junit4]   2> 298171 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   index before flush _1l(4.5):C4 _1m(4.5):C1
   [junit4]   2> 298171 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker startFullFlush
   [junit4]   2> 298172 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 298180 T97 C19 oasu.LoggingInfoStream.message [DWFC][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 153 ]]
   [junit4]   2> 298182 T97 C19 oasu.LoggingInfoStream.message [DWFC][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 153 ]]
   [junit4]   2> 298183 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker finishFullFlush success=true
   [junit4]   2> 298184 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: apply all deletes during flush
   [junit4]   2> 298185 T97 C19 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 298186 T97 C19 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=287 packetCount=0
   [junit4]   2> 298187 T97 C19 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: now merge
   [junit4]   2> 298195 T97 C19 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   index: _1l(4.5):C4 _1m(4.5):C1
   [junit4]   2> 298196 T97 C19 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   no more merges pending; now return
   [junit4]   2> 298199 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: waitForMerges
   [junit4]   2> 298200 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: waitForMerges done
   [junit4]   2> 298201 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: now call final commit()
   [junit4]   2> 298201 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: commit: start
   [junit4]   2> 298202 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: commit: enter lock
   [junit4]   2> 298203 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: commit: now prepare
   [junit4]   2> 298203 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: prepareCommit: flush
   [junit4]   2> 298204 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   index before flush _1l(4.5):C4 _1m(4.5):C1
   [junit4]   2> 298205 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker startFullFlush
   [junit4]   2> 298205 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 298206 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: apply all deletes during flush
   [junit4]   2> 298206 T97 C19 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 298207 T97 C19 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@5d7487fb minGen=287 packetCount=0
   [junit4]   2> 298208 T97 C19 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker finishFullFlush success=true
   [junit4]   2> 298209 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: startCommit(): start
   [junit4]   2> 298209 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]:   skip startCommit(): no changes pending
   [junit4]   2> 298210 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: commit: pendingCommit == null; skip
   [junit4]   2> 298210 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: commit: done
   [junit4]   2> 298211 T97 C19 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingBinaryTest-seed#[619FEC580107CFFD]-worker]: at close: _1l(4.5):C4 _1m(4.5):C1
   [junit4]   2> 298253 T97 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 298267 T97 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 298268 T97 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393;done=false>>]
   [junit4]   2> 298269 T97 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393
   [junit4]   2> 298271 T97 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index;done=false>>]
   [junit4]   2> 298281 T97 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingBinaryTest-1375679224393/index
   [junit4]   2> 298286 T97 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 298428 T97 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=sr__#Latn, timezone=Etc/GMT-9
   [junit4]   2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=9,free=50116184,total=95420416
   [junit4]   2> NOTE: All tests run in this JVM: [SolrExampleJettyTest, MultiCoreExampleJettyTest, SolrExceptionTest, TestCoreAdmin, SolrExampleStreamingBinaryTest]
   [junit4] Completed in 232.59s, 27 tests, 1 error <<< FAILURES!

[...truncated 132 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:395: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:375: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:194: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:449: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error

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