You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/09/01 12:20:57 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b102) - Build
# 7265 - Failure!
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