lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b102) - Build # 7265 - Failure!
Date Sun, 01 Sep 2013 10:20:57 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/7265/
Java: 32bit/jdk1.8.0-ea-b102 -server -XX:+UseSerialGC

1 tests failed.
REGRESSION:  org.apache.solr.client.solrj.SolrExampleBinaryTest.testUnicode

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

Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:37006/solr/collection1
	at __randomizedtesting.SeedInfo.seed([204B7811A2DA242D:3987CC1B0060F5DA]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:436)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:68)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:54)
	at org.apache.solr.client.solrj.SolrExampleTests.testUnicode(SolrExampleTests.java:375)
	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:491)
	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)
	... 45 more




Build Log:
[...truncated 10955 lines...]
   [junit4] Suite: org.apache.solr.client.solrj.SolrExampleBinaryTest
   [junit4]   2> log4j:WARN No such property [conversionPattern] in org.apache.solr.util.SolrLogLayout.
   [junit4]   2> 379 T14 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
   [junit4]   2> 384 T14 oas.SolrTestCaseJ4.initCore ####initCore
   [junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/./solrtest-SolrExampleBinaryTest-1378030576849
   [junit4]   2> 385 T14 oas.SolrTestCaseJ4.initCore ####initCore end
   [junit4]   2> 674 T14 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1005 T14 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
   [junit4]   2> 1043 T14 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:37006
   [junit4]   2> 1066 T14 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1099 T14 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1100 T14 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr
   [junit4]   2> 1101 T14 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/'
   [junit4]   2> 1247 T14 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/solr.xml
   [junit4]   2> 1375 T14 oasc.ConfigSolrXml.<init> Config-defined core root directory: 
   [junit4]   2> 1383 T14 oasc.CoreContainer.<init> New CoreContainer 2243757
   [junit4]   2> 1384 T14 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/]
   [junit4]   2> 1415 T14 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
   [junit4]   2> 1416 T14 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1417 T14 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
   [junit4]   2> 1418 T14 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1418 T14 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1419 T14 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1419 T14 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1420 T14 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1421 T14 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1434 T14 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
   [junit4]   2> 1509 T14 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 1511 T14 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 1579 T14 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr
   [junit4]   2> 1621 T14 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/
   [junit4]   2> 1624 T14 oasc.CorePropertiesLocator.discover Found 1 core definitions
   [junit4]   2> 1626 T26 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1
   [junit4]   2> 1626 T26 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/'
   [junit4]   2> 1767 T26 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
   [junit4]   2> 1769 T26 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../contrib/extraction/lib).
   [junit4]   2> 1769 T26 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 1770 T26 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../contrib/clustering/lib).
   [junit4]   2> 1771 T26 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 1772 T26 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../contrib/langid/lib).
   [junit4]   2> 1772 T26 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 1773 T26 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../contrib/velocity/lib).
   [junit4]   2> 1774 T26 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/../../../dist).
   [junit4]   2> 1846 T26 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
   [junit4]   2> 1852 T26 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
   [junit4]   2> 2127 T26 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 2141 T26 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 2209 T26 oass.IndexSchema.readSchema [null] Schema name=example
   [junit4]   2> 3070 T26 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 3288 T26 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3293 T26 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3443 T26 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 3452 T26 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/
   [junit4]   2> 3454 T26 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@540c69
   [junit4]   2> 3464 T26 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
   [junit4]   2> 3465 T26 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
   [junit4]   2> 3494 T26 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849
   [junit4]   2> 3495 T26 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index/
   [junit4]   2> 3495 T26 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index' doesn't exist. Creating new index...
   [junit4]   2> 3506 T26 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index
   [junit4]   2> 3541 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@86b0e6
   [junit4]   2> 3543 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 3543 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: 0 msec to checkpoint
   [junit4]   2> 3544 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: init: create=true
   [junit4]   2> 3544 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda)
   [junit4]   2> 	index=
   [junit4]   2> 	version=5.0-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_50
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
   [junit4]   2> 	commit=null
   [junit4]   2> 	openMode=CREATE
   [junit4]   2> 	similarity=org.apache.lucene.search.similarities.DefaultSimilarity
   [junit4]   2> 	mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
   [junit4]   2> 	default WRITE_LOCK_TIMEOUT=1000
   [junit4]   2> 	writeLockTimeout=1000
   [junit4]   2> 	codec=Lucene45
   [junit4]   2> 	infoStream=org.apache.solr.update.LoggingInfoStream
   [junit4]   2> 	mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 	indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@aba270
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 3545 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: now flush at close waitForMerges=true
   [junit4]   2> 3545 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]:   start flush: applyAllDeletes=true
   [junit4]   2> 3545 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]:   index before flush 
   [junit4]   2> 3546 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 startFullFlush
   [junit4]   2> 3546 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 3547 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 finishFullFlush success=true
   [junit4]   2> 3547 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: apply all deletes during flush
   [junit4]   2> 3548 T26 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-3-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@9f5871 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 3548 T26 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-3-thread-1]: now merge
   [junit4]   2> 3549 T26 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-3-thread-1]:   index: 
   [junit4]   2> 3549 T26 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-3-thread-1]:   no more merges pending; now return
   [junit4]   2> 3549 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: waitForMerges
   [junit4]   2> 3550 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: waitForMerges done
   [junit4]   2> 3550 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: now call final commit()
   [junit4]   2> 3550 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: start
   [junit4]   2> 3550 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: enter lock
   [junit4]   2> 3551 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: now prepare
   [junit4]   2> 3551 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: prepareCommit: flush
   [junit4]   2> 3551 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]:   index before flush 
   [junit4]   2> 3551 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 startFullFlush
   [junit4]   2> 3552 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 3552 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: apply all deletes during flush
   [junit4]   2> 3552 T26 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-3-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@9f5871 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 3553 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 finishFullFlush success=true
   [junit4]   2> 3553 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: startCommit(): start
   [junit4]   2> 3553 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: startCommit index= changeCount=1
   [junit4]   2> 3557 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: done all syncs: []
   [junit4]   2> 3557 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: pendingCommit != null
   [junit4]   2> 3558 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: wrote segments file "segments_1"
   [junit4]   2> 3566 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
   [junit4]   2> 3571 T26 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_1,generation=1}
   [junit4]   2> 3572 T26 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3573 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: 6 msec to checkpoint
   [junit4]   2> 3573 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: commit: done
   [junit4]   2> 3573 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: at close: 
   [junit4]   2> 3583 T26 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
   [junit4]   2> 3584 T26 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
   [junit4]   2> 3586 T26 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
   [junit4]   2> 3598 T26 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
   [junit4]   2> 3598 T26 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
   [junit4]   2> 3872 T26 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 3894 T26 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
   [junit4]   2> 3896 T26 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
   [junit4]   2> 3902 T26 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 3903 T26 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
   [junit4]   2> 3911 T26 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 3918 T26 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
   [junit4]   2> 3924 T26 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
   [junit4]   2> 3924 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 3926 T26 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
   [junit4]   2> 3926 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
   [junit4]   2> 3926 T26 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
   [junit4]   2> 3927 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 3927 T26 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
   [junit4]   2> 3932 T26 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
   [junit4]   2> 3937 T26 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
   [junit4]   2> 3941 T26 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
   [junit4]   2> 3958 T26 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 3959 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 3959 T26 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
   [junit4]   2> 3960 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 3960 T26 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
   [junit4]   2> 3960 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
   [junit4]   2> 3961 T26 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
   [junit4]   2> 3961 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 3961 T26 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
   [junit4]   2> 3962 T26 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
   [junit4]   2> 3962 T26 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
   [junit4]   2> 4001 T26 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 4012 T26 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 4013 T26 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 4071 T26 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms; 
   [junit4]   2> 4072 T26 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 4075 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@86b0e6
   [junit4]   2> 4076 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: init: load commit "segments_1"
   [junit4]   2> 4077 T26 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_1,generation=1}
   [junit4]   2> 4077 T26 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 4077 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 4078 T26 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-3-thread-1]: 0 msec to checkpoint
   [junit4]   2> 4081 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: init: create=false
   [junit4]   2> 4081 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: 
   [junit4]   2> 	dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda)
   [junit4]   2> 	index=
   [junit4]   2> 	version=5.0-SNAPSHOT
   [junit4]   2> 	matchVersion=LUCENE_50
   [junit4]   2> 	analyzer=null
   [junit4]   2> 	ramBufferSizeMB=100.0
   [junit4]   2> 	maxBufferedDocs=-1
   [junit4]   2> 	maxBufferedDeleteTerms=-1
   [junit4]   2> 	mergedSegmentWarmer=null
   [junit4]   2> 	delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
   [junit4]   2> 	commit=null
   [junit4]   2> 	openMode=APPEND
   [junit4]   2> 	similarity=org.apache.lucene.search.similarities.DefaultSimilarity
   [junit4]   2> 	mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
   [junit4]   2> 	default WRITE_LOCK_TIMEOUT=1000
   [junit4]   2> 	writeLockTimeout=1000
   [junit4]   2> 	codec=Lucene45
   [junit4]   2> 	infoStream=org.apache.solr.update.LoggingInfoStream
   [junit4]   2> 	mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 	indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@f2a367
   [junit4]   2> 	readerPooling=false
   [junit4]   2> 	perThreadHardLimitMB=1945
   [junit4]   2> 	useCompoundFile=false
   [junit4]   2> 	
   [junit4]   2> 4086 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: flush at getReader
   [junit4]   2> 4086 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 startFullFlush
   [junit4]   2> 4087 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 4087 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: apply all deletes during flush
   [junit4]   2> 4087 T26 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-3-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=9223372036854775807 packetCount=0
   [junit4]   2> 4090 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
   [junit4]   2> 4091 T26 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-3-thread-1]: coreLoadExecutor-3-thread-1 finishFullFlush success=true
   [junit4]   2> 4091 T26 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-3-thread-1]: getReader took 5 msec
   [junit4]   2> 4101 T26 oass.SolrIndexSearcher.<init> Opening Searcher@10ea3f2 main
   [junit4]   2> 4119 T26 oashc.SpellCheckComponent.inform Initializing spell checkers
   [junit4]   2> 4143 T26 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> 4177 T26 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
   [junit4]   2> 4182 T26 oashc.QueryElevationComponent.inform Loading QueryElevation from: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/example/solr/collection1/conf/elevate.xml
   [junit4]   2> 4251 T26 oash.ReplicationHandler.inform Commits will be reserved for  10000
   [junit4]   2> 4251 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@10ea3f2 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> ASYNC  NEW_CORE C0 name=collection1 org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 4400 T27 C0 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=142 
   [junit4]   2> 4403 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 4403 T27 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
   [junit4]   2> 4403 T27 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
   [junit4]   2> 4406 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10ea3f2 main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 4412 T26 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 4416 T14 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1
   [junit4]   2> 4416 T14 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 4417 T14 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#37006
   [junit4]   2> 4513 T14 oas.SolrTestCaseJ4.setUp ###Starting testPivotFacets
   [junit4]   2> 4528 T14 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> ASYNC  NEW_CORE C1 name=collection1 org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 5468 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5470 T22 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 5471 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5472 T22 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: flush at getReader
   [junit4]   2> 5472 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 startFullFlush
   [junit4]   2> 5473 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5474 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22: flush naked frozen global deletes
   [junit4]   2> 5483 T22 C1 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: push deletes  1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
   [junit4]   2> 5484 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 5485 T22 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: apply all deletes during flush
   [junit4]   2> 5485 T22 C1 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 5486 T22 C1 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 5487 T22 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
   [junit4]   2> 5488 T22 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 finishFullFlush success=true
   [junit4]   2> 5489 T22 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: getReader took 17 msec
   [junit4]   2> 5501 T22 C1 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444969795406528512)} 0 147
   [junit4]   2> 5644 T23 C1 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 5645 T23 C1 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
   [junit4]   2> 5646 T23 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-23]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5647 T23 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-23]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
   [junit4]   2> 5649 T23 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-23]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5649 T23 C1 oass.SolrIndexSearcher.<init> Opening Searcher@1b8cacc main
   [junit4]   2> 5653 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1b8cacc main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 5654 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 5658 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b8cacc main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 5663 T23 C1 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 5663 T23 C1 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 20
   [junit4]   2> 5706 T24 C1 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=11 
   [junit4]   2> 5923 T22 C1 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1 (1444969795743121408), 2 (1444969795940253696), 3 (1444969795942350848), 4 (1444969795943399424), 5 (1444969795944448000), 6 (1444969795945496576), 7 (1444969795945496577), 8 (1444969795946545152), 9 (1444969795947593728), 10 (1444969795954933760), ... (12 adds)]} 0 207
   [junit4]   2> 5932 T25 C1 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 5936 T25 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: start
   [junit4]   2> 5936 T25 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: enter lock
   [junit4]   2> 5936 T25 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: now prepare
   [junit4]   2> 5937 T25 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: prepareCommit: flush
   [junit4]   2> 5937 T25 C1 oasu.LoggingInfoStream.message [IW][qtp8436347-25]:   index before flush 
   [junit4]   2> 5938 T25 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 5938 T25 C1 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=12 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 5939 T25 C1 oasu.LoggingInfoStream.message [DWFC][qtp8436347-25]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 11 deleted terms (unique count=11) bytesUsed=1510, segment=_0, aborting=false, numDocsInRAM=12, deleteQueue=DWDQ: [ generation: 2 ]]
   [junit4]   2> 5946 T25 C1 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flush postings as segment _0 numDocs=12
   [junit4]   2> ASYNC  NEW_CORE C2 name=collection1 org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 6054 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has 0 deleted docs
   [junit4]   2> 6055 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has no vectors; norms; no docValues; prox; freqs
   [junit4]   2> 6055 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: 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> 6056 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed codec=Lucene45
   [junit4]   2> 6063 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed: segment=_0 ramUsed=0.082 MB newFlushedSize(includes docstores)=0.002 MB docs/MB=7,328.429
   [junit4]   2> 6071 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 6072 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publishFlushedSegment
   [junit4]   2> 6073 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: push deletes  12 deleted terms (unique count=12) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
   [junit4]   2> 6074 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publish sets newSegment delGen=5 seg=_0(5.0):C12
   [junit4]   2> 6082 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_0(5.0):C12" [1 segments ; isCommit = false]
   [junit4]   2> 6083 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 0 msec to checkpoint
   [junit4]   2> 6100 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 6101 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: infos=[_0(5.0):C12] packetCount=1
   [junit4]   2> 6101 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes took 0 msec
   [junit4]   2> 6102 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=6 packetCount=1
   [junit4]   2> 6102 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 6103 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 6105 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]: findMerges: 1 segments
   [junit4]   2> 6115 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   seg=_0(5.0):C12 size=0.001 MB [floored]
   [junit4]   2> 6117 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 6119 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]: now merge
   [junit4]   2> 6119 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   index: _0(5.0):C12
   [junit4]   2> 6121 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   no more merges pending; now return
   [junit4]   2> 6122 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit(): start
   [junit4]   2> 6122 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit index=_0(5.0):C12 changeCount=3
   [junit4]   2> 6127 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: 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> 6128 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: pendingCommit != null
   [junit4]   2> 6129 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: wrote segments file "segments_2"
   [junit4]   2> 6129 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_0(5.0):C12" [1 segments ; isCommit = true]
   [junit4]   2> 6130 T25 C2 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_1,generation=1}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_2,generation=2}
   [junit4]   2> 6130 T25 C2 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
   [junit4]   2> 6131 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: deleteCommits: now decRef commit "segments_1"
   [junit4]   2> 6131 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "segments_1"
   [junit4]   2> 6132 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 2 msec to checkpoint
   [junit4]   2> 6132 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: done
   [junit4]   2> 6135 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6135 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 6136 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: flush at getReader
   [junit4]   2> 6136 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 6137 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6137 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 6137 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: no deletes; skipping
   [junit4]   2> 6138 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=6 packetCount=0
   [junit4]   2> 6194 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)
   [junit4]   2> 6196 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 6196 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: getReader took 60 msec
   [junit4]   2> 6198 T25 C2 oass.SolrIndexSearcher.<init> Opening Searcher@10fddd3 main
   [junit4]   2> 6201 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@10fddd3 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)}
   [junit4]   2> 6202 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 6207 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10fddd3 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)}
   [junit4]   2> 6221 T25 C2 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 6221 T25 C2 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 289
   [junit4]   2> 6324 T24 C2 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=features,memSize=4521,tindexSize=43,time=18,phase1=18,nTerms=2,bigTerms=2,termInstances=0,uses=0}
   [junit4]   2> 6332 T24 C2 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=cat,memSize=4515,tindexSize=41,time=0,phase1=0,nTerms=2,bigTerms=2,termInstances=0,uses=0}
   [junit4]   2> 6348 T24 C2 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet.missing=false&facet=true&facet.mincount=0&q=*:*&wt=javabin&facet.pivot=features,cat&facet.pivot=cat,features&facet.pivot=features,cat,inStock&version=2&rows=0} hits=12 status=0 QTime=120 
   [junit4]   2> 6386 T23 C2 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&wt=javabin&fq={!tag%3Dmytag}-(features:bbb+AND+cat:a+AND+inStock:true)&facet.pivot={!ex%3Dmytag+key%3Dmykey}features,cat&version=2&rows=0} hits=11 status=0 QTime=29 
   [junit4]   2> 6389 T14 oas.SolrTestCaseJ4.tearDown ###Ending testPivotFacets
   [junit4]   2> 6401 T14 oas.SolrTestCaseJ4.setUp ###Starting testSetNullUpdates
   [junit4]   2> 6410 T22 C2 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdates (1444969796466638848)]} 0 2
   [junit4]   2> 6418 T25 C2 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 6418 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: start
   [junit4]   2> 6419 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: enter lock
   [junit4]   2> 6419 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: now prepare
   [junit4]   2> 6419 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: prepareCommit: flush
   [junit4]   2> 6420 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]:   index before flush _0(5.0):C12
   [junit4]   2> 6420 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 6421 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6421 T25 C2 oasu.LoggingInfoStream.message [DWFC][qtp8436347-25]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 4 ]]
   [junit4]   2> 6422 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flush postings as segment _1 numDocs=1
   [junit4]   2> 6425 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has 0 deleted docs
   [junit4]   2> 6425 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 6426 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushedFiles=[_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
   [junit4]   2> 6426 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed codec=Lucene45
   [junit4]   2> 6427 T25 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed: segment=_1 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,154.819
   [junit4]   2> 6427 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 6428 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publishFlushedSegment
   [junit4]   2> 6428 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: push deletes  1 deleted terms (unique count=1) bytesUsed=1024 delGen=8 packetCount=1 totBytesUsed=1024
   [junit4]   2> 6431 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publish sets newSegment delGen=9 seg=_1(5.0):C1
   [junit4]   2> 6432 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_0(5.0):C12 _1(5.0):C1" [2 segments ; isCommit = false]
   [junit4]   2> 6432 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 0 msec to checkpoint
   [junit4]   2> 6433 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 6433 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: infos=[_0(5.0):C12, _1(5.0):C1] packetCount=1
   [junit4]   2> 6475 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: seg=_0(5.0):C12 segGen=6 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
   [junit4]   2> 6476 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes took 43 msec
   [junit4]   2> 6476 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=10 packetCount=1
   [junit4]   2> 6477 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 6477 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 6478 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]: findMerges: 2 segments
   [junit4]   2> 6479 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   seg=_0(5.0):C12 size=0.001 MB [floored]
   [junit4]   2> 6479 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   seg=_1(5.0):C1 size=0.001 MB [floored]
   [junit4]   2> 6480 T25 C2 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   allowedSegmentCount=1 vs count=2 (eligible count=2) tooBigCount=0
   [junit4]   2> 6480 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]: now merge
   [junit4]   2> 6481 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   index: _0(5.0):C12 _1(5.0):C1
   [junit4]   2> 6482 T25 C2 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   no more merges pending; now return
   [junit4]   2> 6483 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit(): start
   [junit4]   2> 6483 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit index=_0(5.0):C12 _1(5.0):C1 changeCount=6
   [junit4]   2> 6485 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: done all syncs: [_1_Lucene41_0.doc, _0.fnm, _0_Lucene41_0.pos, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _0.nvm, _1.fnm, _1.fdx, _1.fdt, _0_Lucene41_0.doc, _1.si, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
   [junit4]   2> 6485 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: pendingCommit != null
   [junit4]   2> 6487 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: wrote segments file "segments_3"
   [junit4]   2> 6488 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_0(5.0):C12 _1(5.0):C1" [2 segments ; isCommit = true]
   [junit4]   2> 6488 T25 C2 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_2,generation=2}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_3,generation=3}
   [junit4]   2> 6489 T25 C2 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
   [junit4]   2> 6489 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: deleteCommits: now decRef commit "segments_2"
   [junit4]   2> 6490 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "segments_2"
   [junit4]   2> 6490 T25 C2 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 2 msec to checkpoint
   [junit4]   2> 6491 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: done
   [junit4]   2> 6491 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6492 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 6492 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: flush at getReader
   [junit4]   2> 6493 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 6493 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6494 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 6495 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: no deletes; skipping
   [junit4]   2> 6495 T25 C2 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=10 packetCount=0
   [junit4]   2> 6499 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: return reader version=5 reader=StandardDirectoryReader(segments_3:5:nrt _0(5.0):C12 _1(5.0):C1)
   [junit4]   2> 6500 T25 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 6500 T25 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: getReader took 8 msec
   [junit4]   2> 6502 T25 C2 oass.SolrIndexSearcher.<init> Opening Searcher@1a68781 main
   [junit4]   2> 6504 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1a68781 main{StandardDirectoryReader(segments_3:5:nrt _0(5.0):C12 _1(5.0):C1)}
   [junit4]   2> 6504 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 6505 T25 C2 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 6507 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a68781 main{StandardDirectoryReader(segments_3:5:nrt _0(5.0):C12 _1(5.0):C1)}
   [junit4]   2> 6509 T25 C2 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 91
   [junit4]   2> 6535 T23 C2 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdates (1444969796597710848)]} 0 21
   [junit4]   2> 6544 T22 C2 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 6545 T22 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: start
   [junit4]   2> 6545 T22 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: enter lock
   [junit4]   2> 6546 T22 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: now prepare
   [junit4]   2> 6546 T22 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: prepareCommit: flush
   [junit4]   2> 6547 T22 C2 oasu.LoggingInfoStream.message [IW][qtp8436347-22]:   index before flush _0(5.0):C12 _1(5.0):C1
   [junit4]   2> 6547 T22 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 startFullFlush
   [junit4]   2> 6548 T22 C2 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6548 T22 C2 oasu.LoggingInfoStream.message [DWFC][qtp8436347-22]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 6 ]]
   [junit4]   2> 6549 T22 C2 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: flush postings as segment _2 numDocs=1
   [junit4]   2> ASYNC  NEW_CORE C3 name=collection1 org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 6566 T22 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: new segment has 0 deleted docs
   [junit4]   2> 6567 T22 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 6567 T22 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: flushedFiles=[_2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
   [junit4]   2> 6568 T22 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: flushed codec=Lucene45
   [junit4]   2> 6569 T22 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-22]: flushed: segment=_2 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,394.383
   [junit4]   2> 6569 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 6570 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: publishFlushedSegment
   [junit4]   2> 6570 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: push deletes  1 deleted terms (unique count=1) bytesUsed=1024 delGen=12 packetCount=1 totBytesUsed=1024
   [junit4]   2> 6570 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: publish sets newSegment delGen=13 seg=_2(5.0):C1
   [junit4]   2> 6571 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "_0(5.0):C12 _1(5.0):C1 _2(5.0):C1" [3 segments ; isCommit = false]
   [junit4]   2> 6571 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 0 msec to checkpoint
   [junit4]   2> 6572 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: apply all deletes during flush
   [junit4]   2> 6572 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: applyDeletes: infos=[_0(5.0):C12, _1(5.0):C1, _2(5.0):C1] packetCount=1
   [junit4]   2> 6575 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: seg=_1(5.0):C1 segGen=10 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=1 100% deleted
   [junit4]   2> 6576 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: seg=_0(5.0):C12 segGen=10 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
   [junit4]   2> 6577 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: applyDeletes took 5 msec
   [junit4]   2> 6577 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "_0(5.0):C12 _1(5.0):C1/1 _2(5.0):C1" [3 segments ; isCommit = false]
   [junit4]   2> 6578 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 0 msec to checkpoint
   [junit4]   2> 6592 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: drop 100% deleted segments: _1(5.0):C1/1
   [junit4]   2> 6593 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "_0(5.0):C12 _2(5.0):C1" [2 segments ; isCommit = false]
   [junit4]   2> 6593 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 0 msec to checkpoint
   [junit4]   2> 6594 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=14 packetCount=1
   [junit4]   2> 6594 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 6595 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 finishFullFlush success=true
   [junit4]   2> 6595 T22 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-22]: findMerges: 2 segments
   [junit4]   2> 6596 T22 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-22]:   seg=_0(5.0):C12 size=0.001 MB [floored]
   [junit4]   2> 6597 T22 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-22]:   seg=_2(5.0):C1 size=0.001 MB [floored]
   [junit4]   2> 6597 T22 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-22]:   allowedSegmentCount=1 vs count=2 (eligible count=2) tooBigCount=0
   [junit4]   2> 6601 T22 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-22]: now merge
   [junit4]   2> 6602 T22 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-22]:   index: _0(5.0):C12 _2(5.0):C1
   [junit4]   2> 6602 T22 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-22]:   no more merges pending; now return
   [junit4]   2> 6602 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: startCommit(): start
   [junit4]   2> 6603 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: startCommit index=_0(5.0):C12 _2(5.0):C1 changeCount=11
   [junit4]   2> 6604 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: done all syncs: [_2.si, _0.fnm, _2_Lucene41_0.tim, _0_Lucene41_0.pos, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _0.nvm, _2.fdx, _2.fnm, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
   [junit4]   2> 6604 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: pendingCommit != null
   [junit4]   2> 6605 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: wrote segments file "segments_4"
   [junit4]   2> 6605 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "_0(5.0):C12 _2(5.0):C1" [2 segments ; isCommit = true]
   [junit4]   2> 6605 T22 C3 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_3,generation=3}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_4,generation=4}
   [junit4]   2> 6618 T22 C3 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
   [junit4]   2> 6618 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: deleteCommits: now decRef commit "segments_3"
   [junit4]   2> 6619 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 6620 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 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> 6620 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 6621 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 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> 6621 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1_Lucene41_0.tip"
   [junit4]   2> 6622 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1.fnm"
   [junit4]   2> 6622 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1.fdx"
   [junit4]   2> 6622 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1.fdt"
   [junit4]   2> 6623 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 6623 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "_1.si"
   [junit4]   2> 6623 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: delete "segments_3"
   [junit4]   2> 6624 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 18 msec to checkpoint
   [junit4]   2> 6624 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: commit: done
   [junit4]   2> 6625 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6625 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 6626 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: flush at getReader
   [junit4]   2> 6626 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 startFullFlush
   [junit4]   2> 6626 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6627 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: apply all deletes during flush
   [junit4]   2> 6627 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: applyDeletes: no deletes; skipping
   [junit4]   2> 6628 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=14 packetCount=0
   [junit4]   2> 6629 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: return reader version=9 reader=StandardDirectoryReader(segments_4:9:nrt _0(5.0):C12 _2(5.0):C1)
   [junit4]   2> 6630 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 finishFullFlush success=true
   [junit4]   2> 6630 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: getReader took 4 msec
   [junit4]   2> 6631 T22 C3 oass.SolrIndexSearcher.<init> Opening Searcher@2cbdbf main
   [junit4]   2> 6632 T22 C3 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 6640 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@2cbdbf main{StandardDirectoryReader(segments_4:9:nrt _0(5.0):C12 _2(5.0):C1)}
   [junit4]   2> 6641 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 6644 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2cbdbf main{StandardDirectoryReader(segments_4:9:nrt _0(5.0):C12 _2(5.0):C1)}
   [junit4]   2> 6645 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _1_Lucene41_0.doc
   [junit4]   2> 6645 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_1_Lucene41_0.doc"
   [junit4]   2> 6646 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _1_Lucene41_0.tim
   [junit4]   2> 6646 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_1_Lucene41_0.tim"
   [junit4]   2> 6646 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _1.fdt
   [junit4]   2> 6646 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_1.fdt"
   [junit4]   2> 6647 T22 C3 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 103
   [junit4]   2> 6652 T25 C3 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:testSetNullUpdates&wt=javabin&version=2} hits=1 status=0 QTime=1 
   [junit4]   2> 6655 T14 oas.SolrTestCaseJ4.tearDown ###Ending testSetNullUpdates
   [junit4]   2> 6681 T14 oas.SolrTestCaseJ4.setUp ###Starting testUnicode
   [junit4]   2> 6691 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6692 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
   [junit4]   2> 6692 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6693 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: flush at getReader
   [junit4]   2> 6693 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 startFullFlush
   [junit4]   2> 6694 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6694 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22: flush naked frozen global deletes
   [junit4]   2> 6695 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: push deletes  1 deleted queries bytesUsed=32 delGen=16 packetCount=1 totBytesUsed=32
   [junit4]   2> 6695 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: flush: push buffered deletes:  1 deleted queries bytesUsed=32
   [junit4]   2> 6695 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: apply all deletes during flush
   [junit4]   2> 6696 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: applyDeletes: infos=[_0(5.0):C12, _2(5.0):C1] packetCount=1
   [junit4]   2> 6771 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: seg=_2(5.0):C1 segGen=14 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
   [junit4]   2> 6772 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: seg=_0(5.0):C12 segGen=14 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=12 100% deleted
   [junit4]   2> 6772 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: applyDeletes took 76 msec
   [junit4]   2> 6773 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "_0(5.0):C12/12 _2(5.0):C1/1" [2 segments ; isCommit = false]
   [junit4]   2> 6773 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 0 msec to checkpoint
   [junit4]   2> 6773 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: drop 100% deleted segments: _2(5.0):C1/1 _0(5.0):C12/12
   [junit4]   2> 6774 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: now checkpoint "" [0 segments ; isCommit = false]
   [junit4]   2> 6774 T22 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-22]: 0 msec to checkpoint
   [junit4]   2> 6775 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=9223372036854775807 packetCount=1
   [junit4]   2> 6775 T22 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-22]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 6776 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: return reader version=11 reader=StandardDirectoryReader(segments_4:11:nrt)
   [junit4]   2> 6791 T22 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-22]: qtp8436347-22 finishFullFlush success=true
   [junit4]   2> 6792 T22 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-22]: getReader took 99 msec
   [junit4]   2> 6792 T22 C3 oass.SolrIndexSearcher.<init> Opening Searcher@1796e89 realtime
   [junit4]   2> 6793 T22 C3 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1444969796762337280)} 0 103
   [junit4]   2> 6962 T24 C3 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[0 (1444969796995121152), 1 (1444969796996169728), 2 (1444969797003509760), 3 (1444969797004558336), 4 (1444969797004558337), 5 (1444969797012946944), 6 (1444969797013995520), 7 (1444969797013995521), 8 (1444969797015044096), 9 (1444969797029724160), ... (24 adds)]} 0 50
   [junit4]   2> 6974 T25 C3 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
   [junit4]   2> 6975 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: start
   [junit4]   2> 6975 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: enter lock
   [junit4]   2> 6976 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: now prepare
   [junit4]   2> 6976 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: prepareCommit: flush
   [junit4]   2> 6976 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]:   index before flush 
   [junit4]   2> 6977 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 6977 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=24 deletes=true hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 6977 T25 C3 oasu.LoggingInfoStream.message [DWFC][qtp8436347-25]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 23 deleted terms (unique count=23) bytesUsed=3165, segment=_3, aborting=false, numDocsInRAM=24, deleteQueue=DWDQ: [ generation: 9 ]]
   [junit4]   2> 6978 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flush postings as segment _3 numDocs=24
   [junit4]   2> 6995 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has 0 deleted docs
   [junit4]   2> 6996 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: new segment has no vectors; no norms; no docValues; no prox; no freqs
   [junit4]   2> 6996 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushedFiles=[_3.fdx, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.fnm, _3_Lucene41_0.tim, _3.fdt]
   [junit4]   2> 6997 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed codec=Lucene45
   [junit4]   2> 6997 T25 C3 oasu.LoggingInfoStream.message [DWPT][qtp8436347-25]: flushed: segment=_3 ramUsed=0.068 MB newFlushedSize(includes docstores)=0.003 MB docs/MB=9,013.547
   [junit4]   2> 6998 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: publishFlushedSegment seg-private deletes=null
   [junit4]   2> 6998 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publishFlushedSegment
   [junit4]   2> 6999 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: push deletes  24 deleted terms (unique count=24) bytesUsed=1024 delGen=18 packetCount=1 totBytesUsed=1024
   [junit4]   2> 6999 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: publish sets newSegment delGen=19 seg=_3(5.0):C24
   [junit4]   2> 6999 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_3(5.0):C24" [1 segments ; isCommit = false]
   [junit4]   2> 7000 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 0 msec to checkpoint
   [junit4]   2> 7000 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 7001 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: infos=[_3(5.0):C24] packetCount=1
   [junit4]   2> 7001 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes took 0 msec
   [junit4]   2> 7002 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=20 packetCount=1
   [junit4]   2> 7002 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: pruneDeletes: prune 1 packets; 0 packets remain
   [junit4]   2> 7002 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 7003 T25 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]: findMerges: 1 segments
   [junit4]   2> 7003 T25 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   seg=_3(5.0):C24 size=0.003 MB [floored]
   [junit4]   2> 7004 T25 C3 oasu.LoggingInfoStream.message [TMP][qtp8436347-25]:   allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
   [junit4]   2> 7004 T25 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]: now merge
   [junit4]   2> 7005 T25 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   index: _3(5.0):C24
   [junit4]   2> 7005 T25 C3 oasu.LoggingInfoStream.message [CMS][qtp8436347-25]:   no more merges pending; now return
   [junit4]   2> 7005 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit(): start
   [junit4]   2> 7006 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: startCommit index=_3(5.0):C24 changeCount=16
   [junit4]   2> 7006 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: done all syncs: [_3.fdx, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.si, _3.fdt, _3_Lucene41_0.tim, _3.fnm]
   [junit4]   2> 7007 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: pendingCommit != null
   [junit4]   2> 7007 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: wrote segments file "segments_5"
   [junit4]   2> 7008 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: now checkpoint "_3(5.0):C24" [1 segments ; isCommit = true]
   [junit4]   2> 7008 T25 C3 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_4,generation=4}
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ebbcc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ffbda),segFN=segments_5,generation=5}
   [junit4]   2> 7015 T25 C3 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
   [junit4]   2> 7015 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: deleteCommits: now decRef commit "segments_4"
   [junit4]   2> 7016 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2.si"
   [junit4]   2> 7016 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2_Lucene41_0.tim"
   [junit4]   2> 7017 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7017 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.fnm"
   [junit4]   2> 7017 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 7018 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7018 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2.fdt"
   [junit4]   2> 7019 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2.fdt": java.io.IOException: MockDirectoryWrapper: file "_2.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7019 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2_Lucene41_0.doc"
   [junit4]   2> 7020 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7020 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2_Lucene41_0.tip"
   [junit4]   2> 7021 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.nvm"
   [junit4]   2> 7021 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2.fdx"
   [junit4]   2> 7022 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2.fnm"
   [junit4]   2> 7022 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 7022 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7023 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.nvd"
   [junit4]   2> 7023 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7024 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.fdx"
   [junit4]   2> 7024 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.si"
   [junit4]   2> 7025 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 7025 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7025 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.tip"
   [junit4]   2> 7026 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.fdt"
   [junit4]   2> 7026 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7027 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "segments_4"
   [junit4]   2> 7027 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 19 msec to checkpoint
   [junit4]   2> 7028 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: commit: done
   [junit4]   2> 7028 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 7029 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
   [junit4]   2> 7029 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: flush at getReader
   [junit4]   2> 7029 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 startFullFlush
   [junit4]   2> 7030 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 7030 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: apply all deletes during flush
   [junit4]   2> 7031 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: applyDeletes: no deletes; skipping
   [junit4]   2> 7031 T25 C3 oasu.LoggingInfoStream.message [BD][qtp8436347-25]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=20 packetCount=0
   [junit4]   2> 7033 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: return reader version=13 reader=StandardDirectoryReader(segments_5:13:nrt _3(5.0):C24)
   [junit4]   2> 7033 T25 C3 oasu.LoggingInfoStream.message [DW][qtp8436347-25]: qtp8436347-25 finishFullFlush success=true
   [junit4]   2> 7033 T25 C3 oasu.LoggingInfoStream.message [IW][qtp8436347-25]: getReader took 4 msec
   [junit4]   2> 7034 T25 C3 oass.SolrIndexSearcher.<init> Opening Searcher@121c8da main
   [junit4]   2> 7039 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _2_Lucene41_0.tim
   [junit4]   2> 7040 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2_Lucene41_0.tim"
   [junit4]   2> 7040 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7041 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 7041 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 7042 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7042 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _2.fdt
   [junit4]   2> 7042 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2.fdt"
   [junit4]   2> 7043 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2.fdt": java.io.IOException: MockDirectoryWrapper: file "_2.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7043 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _2_Lucene41_0.doc
   [junit4]   2> 7044 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_2_Lucene41_0.doc"
   [junit4]   2> 7044 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_2_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7045 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 7045 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 7045 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7046 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _0.nvd
   [junit4]   2> 7046 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.nvd"
   [junit4]   2> 7047 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7047 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 7047 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 7048 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: 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> 7048 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete pending file _0.fdt
   [junit4]   2> 7049 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: delete "_0.fdt"
   [junit4]   2> 7049 T25 C3 oasu.LoggingInfoStream.message [IFD][qtp8436347-25]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
   [junit4]   2> 7050 T25 C3 oasu.DirectUpdateHandler2.commit end_commit_flush
   [junit4]   2> 7050 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@121c8da main{StandardDirectoryReader(segments_5:13:nrt _3(5.0):C24)}
   [junit4]   2> 7051 T27 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
   [junit4]   2> 7055 T27 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@121c8da main{StandardDirectoryReader(segments_5:13:nrt _3(5.0):C24)}
   [junit4]   2> 7057 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _2_Lucene41_0.tim
   [junit4]   2> 7057 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_2_Lucene41_0.tim"
   [junit4]   2> 7057 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _0_Lucene41_0.pos
   [junit4]   2> 7058 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_0_Lucene41_0.pos"
   [junit4]   2> 7058 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _2.fdt
   [junit4]   2> 7058 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_2.fdt"
   [junit4]   2> 7058 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _2_Lucene41_0.doc
   [junit4]   2> 7059 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_2_Lucene41_0.doc"
   [junit4]   2> 7059 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _0_Lucene41_0.doc
   [junit4]   2> 7059 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_0_Lucene41_0.doc"
   [junit4]   2> 7059 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _0.nvd
   [junit4]   2> 7060 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_0.nvd"
   [junit4]   2> 7060 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _0_Lucene41_0.tim
   [junit4]   2> 7060 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_0_Lucene41_0.tim"
   [junit4]   2> 7060 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete pending file _0.fdt
   [junit4]   2> 7061 T27 oasu.LoggingInfoStream.message [IFD][searcherExecutor-4-thread-1]: delete "_0.fdt"
   [junit4]   2> 7063 T25 C3 oasup.LogUpdateProcessor.fi

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

softCommit=false} {commit=} 0 34
   [junit4]   2> 214233 T25 C16 oasc.SolrCore.execute [collection1] webapp=/solr path=/get params={id=DOCID&fl=id,name,aaa:[value+v%3Daaa]&wt=javabin&qt=/get&version=2} status=0 QTime=1 
   [junit4]   2> 214236 T23 C16 oasc.SolrCore.execute [collection1] webapp=/solr path=/get params={id=DOCID&fl=id,name,aaa:[value+v%3Daaa]&wt=xml&qt=/get&version=2.2} status=0 QTime=0 
   [junit4]   2> 214239 T14 oas.SolrTestCaseJ4.tearDown ###Ending testRealtimeGet
   [junit4]   2> 214340 T14 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2243757
   [junit4]   2> 214341 T14 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 214362 T14 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=63,autocommit maxTime=15000ms,autocommits=1,soft autocommits=3,optimizes=2,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=1,cumulative_adds=265,cumulative_deletesById=5,cumulative_deletesByQuery=31,cumulative_errors=1}
   [junit4]   2> 214363 T14 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
   [junit4]   2> 214363 T14 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
   [junit4]   2> 214363 T14 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
   [junit4]   2> ASYNC  NEW_CORE C17 name=collection1 org.apache.solr.core.SolrCore@10e9794
   [junit4]   2> 214365 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: now flush at close waitForMerges=true
   [junit4]   2> 214365 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   start flush: applyAllDeletes=true
   [junit4]   2> 214365 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   index before flush _18(5.0):C1
   [junit4]   2> 214366 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker startFullFlush
   [junit4]   2> 214366 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 214367 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker finishFullFlush success=true
   [junit4]   2> 214367 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: apply all deletes during flush
   [junit4]   2> 214367 T14 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 214367 T14 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=256 packetCount=0
   [junit4]   2> 214368 T14 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: now merge
   [junit4]   2> 214368 T14 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   index: _18(5.0):C1
   [junit4]   2> 214368 T14 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   no more merges pending; now return
   [junit4]   2> 214368 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: waitForMerges
   [junit4]   2> 214369 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: waitForMerges done
   [junit4]   2> 214369 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: now call final commit()
   [junit4]   2> 214369 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: commit: start
   [junit4]   2> 214369 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: commit: enter lock
   [junit4]   2> 214369 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: commit: now prepare
   [junit4]   2> 214370 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: prepareCommit: flush
   [junit4]   2> 214370 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   index before flush _18(5.0):C1
   [junit4]   2> 214370 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker startFullFlush
   [junit4]   2> 214370 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
   [junit4]   2> 214371 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: apply all deletes during flush
   [junit4]   2> 214371 T14 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: applyDeletes: no deletes; skipping
   [junit4]   2> 214371 T14 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@5abe40 minGen=256 packetCount=0
   [junit4]   2> 214371 T14 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker finishFullFlush success=true
   [junit4]   2> 214372 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: startCommit(): start
   [junit4]   2> 214372 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]:   skip startCommit(): no changes pending
   [junit4]   2> 214372 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: commit: pendingCommit == null; skip
   [junit4]   2> 214372 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: commit: done
   [junit4]   2> 214373 T14 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleBinaryTest-seed#[204B7811A2DA242D]-worker]: at close: _18(5.0):C1
   [junit4]   2> 214373 T14 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
   [junit4]   2> 214374 T14 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
   [junit4]   2> 214375 T14 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index;done=false>>]
   [junit4]   2> 214375 T14 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849/index
   [junit4]   2> 214375 T14 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849;done=false>>]
   [junit4]   2> 214376 T14 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleBinaryTest-1378030576849
   [junit4]   2> 214377 T14 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
   [junit4]   2> 214430 T14 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=CheapBastard, sim=DefaultSimilarity, locale=be_BY, timezone=Africa/Lusaka
   [junit4]   2> NOTE: Linux 3.2.0-52-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=37742456,total=65011712
   [junit4]   2> NOTE: All tests run in this JVM: [IteratorChainTest, SolrExampleBinaryTest]
   [junit4] Completed on J1 in 214.50s, 26 tests, 1 error <<< FAILURES!

[...truncated 37 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:396: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:376: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:202: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:455: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1230: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:873: There were test failures: 46 suites, 272 tests, 1 error

Total time: 40 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b102 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message