You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/08/11 10:12:08 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 701 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/701/
Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.SolrExampleXMLTest.testAddDelete
Error Message:
IOException occured when talking to server at: https://127.0.0.1:54480/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:54480/solr/collection1
at __randomizedtesting.SeedInfo.seed([A32C48ABC2B4E360:6BCC35A1331C30B6]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.client.solrj.SolrExampleTests.testAddDelete(SolrExampleTests.java:736)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 45 more
Build Log:
[...truncated 10861 lines...]
[junit4] Suite: org.apache.solr.client.solrj.SolrExampleXMLTest
[junit4] 2> 273268 T510 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 273269 T510 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleXMLTest-1376208390793
[junit4] 2> 273271 T510 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 273275 T510 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 273331 T510 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 273340 T510 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:54480
[junit4] 2> 273346 T510 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 273351 T510 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 273352 T510 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 273353 T510 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/'
[junit4] 2> 273430 T510 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 273710 T510 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 273711 T510 oasc.CoreContainer.<init> New CoreContainer 1064082924
[junit4] 2> 273712 T510 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/]
[junit4] 2> 273717 T510 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 273718 T510 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 273719 T510 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 273719 T510 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 273720 T510 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 273721 T510 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 273721 T510 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 273722 T510 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 273722 T510 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 273723 T510 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 273769 T510 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 273794 T510 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/
[junit4] 2> 273796 T510 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 273798 T520 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1
[junit4] 2> 273798 T520 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 273898 T520 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 273900 T520 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 273901 T520 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 273902 T520 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 273902 T520 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 273903 T520 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 273904 T520 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 273905 T520 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 273906 T520 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 274058 T520 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 274079 T520 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 274367 T520 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 274369 T520 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 274422 T520 oass.IndexSchema.readSchema [collection1] Schema name=example
[junit4] 2> 277332 T520 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 277395 T520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 277409 T520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 277544 T520 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 277545 T520 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/
[junit4] 2> 277545 T520 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1174335c
[junit4] 2> 277547 T520 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 277548 T520 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 277551 T520 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793
[junit4] 2> 277552 T520 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index/
[junit4] 2> 277553 T520 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index' doesn't exist. Creating new index...
[junit4] 2> 277553 T520 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index
[junit4] 2> 277566 T520 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-267-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@c9d1b58
[junit4] 2> 277567 T520 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-267-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 277568 T520 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-267-thread-1]: 0 msec to checkpoint
[junit4] 2> 277569 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: init: create=true
[junit4] 2> 277569 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@1e6e34e0
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 277570 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 277571 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 277571 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: index before flush
[junit4] 2> 277571 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: coreLoadExecutor-267-thread-1 startFullFlush
[junit4] 2> 277572 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 277573 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: coreLoadExecutor-267-thread-1 finishFullFlush success=true
[junit4] 2> 277573 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: apply all deletes during flush
[junit4] 2> 277574 T520 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-267-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@55516dbb minGen=9223372036854775807 packetCount=0
[junit4] 2> 277574 T520 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-267-thread-1]: now merge
[junit4] 2> 277575 T520 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-267-thread-1]: index:
[junit4] 2> 277575 T520 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-267-thread-1]: no more merges pending; now return
[junit4] 2> 277575 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: waitForMerges
[junit4] 2> 277576 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: waitForMerges done
[junit4] 2> 277576 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: now call final commit()
[junit4] 2> 277577 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: start
[junit4] 2> 277577 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: enter lock
[junit4] 2> 277577 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: now prepare
[junit4] 2> 277578 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: prepareCommit: flush
[junit4] 2> 277578 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: index before flush
[junit4] 2> 277578 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: coreLoadExecutor-267-thread-1 startFullFlush
[junit4] 2> 277579 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 277579 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: apply all deletes during flush
[junit4] 2> 277580 T520 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-267-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@55516dbb minGen=9223372036854775807 packetCount=0
[junit4] 2> 277580 T520 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-267-thread-1]: coreLoadExecutor-267-thread-1 finishFullFlush success=true
[junit4] 2> 277582 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: startCommit(): start
[junit4] 2> 277583 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: startCommit index= changeCount=1
[junit4] 2> 277583 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: done all syncs: []
[junit4] 2> 277584 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: pendingCommit != null
[junit4] 2> 277585 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 277585 T520 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-267-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 277586 T520 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_1,generation=1}
[junit4] 2> 277587 T520 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 277587 T520 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-267-thread-1]: 1 msec to checkpoint
[junit4] 2> 277588 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: commit: done
[junit4] 2> 277588 T520 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-267-thread-1]: at close:
[junit4] 2> 277590 T520 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 277591 T520 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 277591 T520 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 277592 T520 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 277593 T520 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 277606 T520 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 277607 T520 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 277608 T520 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 277609 T520 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 277610 T520 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 277613 T520 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 277617 T520 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 277618 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 277620 T520 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 277621 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 277622 T520 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 277624 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 277625 T520 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 277626 T520 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 277627 T520 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 277629 T520 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 277630 T520 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 277631 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 277631 T520 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 277632 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 277633 T520 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 277633 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 277634 T520 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 277634 T520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 277635 T520 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 277661 T520 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 277667 T520 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 277670 T520 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 277683 T520 oass.SolrIndexSearcher.<init> Opening Searcher@7e7f9d6b main
[junit4] 2> 277685 T520 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 277686 T520 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 277687 T520 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 277687 T520 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> 277688 T520 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 277689 T520 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 277774 T520 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 277775 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@7e7f9d6b main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> ASYNC NEW_CORE C83 name=collection1 org.apache.solr.core.SolrCore@292b63a7
[junit4] 2> 277780 T521 C83 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=5
[junit4] 2> 277780 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 277781 T521 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 277781 T521 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 277793 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e7f9d6b main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 277811 T520 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 277814 T510 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 277814 T510 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 277816 T510 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#54480
[junit4] 2> 277841 T510 oas.SolrTestCaseJ4.setUp ###Starting testPingHandler
[junit4] 2> 277843 T510 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 277990 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@c9d1b58
[junit4] 2> 277991 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: init: load commit "segments_1"
[junit4] 2> 277996 T514 C83 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_1,generation=1}
[junit4] 2> 278002 T514 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 278003 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 278005 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: 1 msec to checkpoint
[junit4] 2> 278006 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: init: create=false
[junit4] 2> 278007 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@25501615
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 278010 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: flush at getReader
[junit4] 2> 278011 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: qtp648392891-514 startFullFlush
[junit4] 2> 278013 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278014 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: qtp648392891-514: flush naked frozen global deletes
[junit4] 2> 278015 T514 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-514]: push deletes 1 deleted queries bytesUsed=36 delGen=1 packetCount=1 totBytesUsed=36
[junit4] 2> 278016 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 278017 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: apply all deletes during flush
[junit4] 2> 278018 T514 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-514]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=1
[junit4] 2> 278019 T514 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-514]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 278020 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 278021 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: qtp648392891-514 finishFullFlush success=true
[junit4] 2> 278022 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: getReader took 12 msec
[junit4] 2> 278023 T514 C83 oass.SolrIndexSearcher.<init> Opening Searcher@5022ac3e realtime
[junit4] 2> 278025 T514 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1443059094528196608)} 0 41
[junit4] 2> 278042 T515 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 278044 T515 C83 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 278046 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278047 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 278048 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278048 T515 C83 oass.SolrIndexSearcher.<init> Opening Searcher@5851c387 main
[junit4] 2> 278050 T515 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 278051 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@5851c387 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 278052 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 278057 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5851c387 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 278059 T515 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 17
[junit4] 2> 278070 T516 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=0
[junit4] 2> 278080 T517 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/admin/ping params={wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 278081 T517 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/admin/ping params={wt=xml&version=2.2} status=0 QTime=2
[junit4] 2> 278085 T510 oas.SolrTestCaseJ4.tearDown ###Ending testPingHandler
[junit4] 2> 278140 T510 oas.SolrTestCaseJ4.setUp ###Starting testCommitWithinOnDelete
[junit4] 2> 278158 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278160 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 278161 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278162 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: flush at getReader
[junit4] 2> 278162 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518 startFullFlush
[junit4] 2> 278163 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278164 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518: flush naked frozen global deletes
[junit4] 2> 278166 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: push deletes 1 deleted queries bytesUsed=36 delGen=3 packetCount=1 totBytesUsed=36
[junit4] 2> 278167 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 278169 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: apply all deletes during flush
[junit4] 2> 278169 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=1
[junit4] 2> 278171 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 278177 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 278178 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518 finishFullFlush success=true
[junit4] 2> 278179 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: getReader took 17 msec
[junit4] 2> 278180 T518 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1443059094707503104)} 0 25
[junit4] 2> 278236 T519 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 278237 T519 C83 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 278238 T519 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-519]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278239 T519 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-519]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 278240 T519 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-519]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278241 T519 C83 oass.SolrIndexSearcher.<init> Opening Searcher@b146a28 main
[junit4] 2> 278243 T519 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 278244 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@b146a28 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 278245 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 278250 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b146a28 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 278252 T519 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 16
[junit4] 2> 278264 T514 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 278280 T515 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[id3 (1443059094830186496)]} 0 7
[junit4] 2> 278310 T517 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 278311 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: start
[junit4] 2> 278311 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: enter lock
[junit4] 2> 278312 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: now prepare
[junit4] 2> 278313 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: prepareCommit: flush
[junit4] 2> 278313 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: index before flush
[junit4] 2> 278314 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 startFullFlush
[junit4] 2> 278316 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278317 T517 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-517]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 278318 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: flush postings as segment _0 numDocs=1
[junit4] 2> 278324 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: new segment has 0 deleted docs
[junit4] 2> 278329 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 278333 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: 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> 278334 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: flushed codec=Lucene42
[junit4] 2> 278335 T517 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-517]: flushed: segment=_0 ramUsed=0.08 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=696.728
[junit4] 2> 278336 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 278338 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: publishFlushedSegment
[junit4] 2> 278339 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=5 packetCount=1 totBytesUsed=1024
[junit4] 2> 278339 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: publish sets newSegment delGen=6 seg=_0(4.5):C1
[junit4] 2> 278340 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 278341 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: 1 msec to checkpoint
[junit4] 2> 278342 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: apply all deletes during flush
[junit4] 2> 278342 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
[junit4] 2> 278343 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: applyDeletes took 1 msec
[junit4] 2> 278344 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=7 packetCount=1
[junit4] 2> 278344 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 278346 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 finishFullFlush success=true
[junit4] 2> 278347 T517 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-517]: findMerges: 1 segments
[junit4] 2> 278348 T517 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-517]: seg=_0(4.5):C1 size=0.001 MB [floored]
[junit4] 2> 278349 T517 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-517]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 278349 T517 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-517]: now merge
[junit4] 2> 278350 T517 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-517]: index: _0(4.5):C1
[junit4] 2> 278351 T517 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-517]: no more merges pending; now return
[junit4] 2> 278351 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: startCommit(): start
[junit4] 2> 278352 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: startCommit index=_0(4.5):C1 changeCount=3
[junit4] 2> 278353 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: 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> 278354 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: pendingCommit != null
[junit4] 2> 278355 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: wrote segments file "segments_2"
[junit4] 2> 278356 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 278357 T517 C83 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_2,generation=2}
[junit4] 2> 278358 T517 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 278359 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 278359 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: delete "segments_1"
[junit4] 2> 278360 T517 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-517]: 4 msec to checkpoint
[junit4] 2> 278361 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: commit: done
[junit4] 2> 278362 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278363 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 278364 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: flush at getReader
[junit4] 2> 278365 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 startFullFlush
[junit4] 2> 278369 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 278371 T517 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-517]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 3 ]]
[junit4] 2> 278372 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: apply all deletes during flush
[junit4] 2> 278373 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: applyDeletes: no deletes; skipping
[junit4] 2> 278374 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=7 packetCount=0
[junit4] 2> 278378 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)
[junit4] 2> 278379 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 finishFullFlush success=true
[junit4] 2> 278380 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: getReader took 16 msec
[junit4] 2> 278381 T517 C83 oass.SolrIndexSearcher.<init> Opening Searcher@3f41a8ad main
[junit4] 2> 278382 T517 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 278383 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@3f41a8ad main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 278383 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 278388 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f41a8ad main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 278390 T517 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 80
[junit4] 2> 278433 T519 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=1 status=0 QTime=3
[junit4] 2> 278497 T514 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {delete=[id3 (-1443059095057727488)]} 0 8
[junit4] 2> 278542 T515 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=1 status=0 QTime=1
[junit4] 2> 278803 T516 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=1 status=0 QTime=0
[junit4] 2> 279063 T518 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=1 status=0 QTime=0
[junit4] 2> 279323 T519 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=1 status=0 QTime=0
[junit4] 2> 279497 T524 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 279498 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279499 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 279500 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279500 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: flush at getReader
[junit4] 2> 279501 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: commitScheduler-271-thread-1 startFullFlush
[junit4] 2> 279501 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279502 T524 oasu.LoggingInfoStream.message [DWFC][commitScheduler-271-thread-1]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 4 ]]
[junit4] 2> 279503 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: commitScheduler-271-thread-1: flush naked frozen global deletes
[junit4] 2> 279509 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=9 packetCount=1 totBytesUsed=1024
[junit4] 2> 279510 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: flush: push buffered deletes: 1 deleted terms (unique count=1) bytesUsed=1024
[junit4] 2> 279511 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: apply all deletes during flush
[junit4] 2> 279511 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
[junit4] 2> 279516 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: seg=_0(4.5):C1 segGen=7 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=1 100% deleted
[junit4] 2> 279517 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: applyDeletes took 6 msec
[junit4] 2> 279518 T524 oasu.LoggingInfoStream.message [IFD][commitScheduler-271-thread-1]: now checkpoint "_0(4.5):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 279518 T524 oasu.LoggingInfoStream.message [IFD][commitScheduler-271-thread-1]: 0 msec to checkpoint
[junit4] 2> 279519 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: drop 100% deleted segments: _0(4.5):C1/1
[junit4] 2> 279519 T524 oasu.LoggingInfoStream.message [IFD][commitScheduler-271-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 279520 T524 oasu.LoggingInfoStream.message [IFD][commitScheduler-271-thread-1]: 0 msec to checkpoint
[junit4] 2> 279521 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=1
[junit4] 2> 279521 T524 oasu.LoggingInfoStream.message [BD][commitScheduler-271-thread-1]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 279522 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 279522 T524 oasu.LoggingInfoStream.message [DW][commitScheduler-271-thread-1]: commitScheduler-271-thread-1 finishFullFlush success=true
[junit4] 2> 279523 T524 oasu.LoggingInfoStream.message [IW][commitScheduler-271-thread-1]: getReader took 23 msec
[junit4] 2> 279523 T524 oass.SolrIndexSearcher.<init> Opening Searcher@6dbbc648 main
[junit4] 2> 279526 T524 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 279527 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@6dbbc648 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 279529 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 279535 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6dbbc648 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 279583 T515 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 279586 T510 oas.SolrTestCaseJ4.tearDown ###Ending testCommitWithinOnDelete
[junit4] 2> 279629 T510 oas.SolrTestCaseJ4.setUp ###Starting testStreamingRequest
[junit4] 2> 279641 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279642 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 279642 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279643 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: flush at getReader
[junit4] 2> 279643 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 startFullFlush
[junit4] 2> 279644 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279644 T517 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-517]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 279645 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517: flush naked frozen global deletes
[junit4] 2> 279645 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: push deletes 1 deleted queries bytesUsed=36 delGen=11 packetCount=1 totBytesUsed=36
[junit4] 2> 279646 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 279646 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: apply all deletes during flush
[junit4] 2> 279647 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=1
[junit4] 2> 279648 T517 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-517]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 279648 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 279649 T517 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-517]: qtp648392891-517 finishFullFlush success=true
[junit4] 2> 279649 T517 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-517]: getReader took 6 msec
[junit4] 2> 279650 T517 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1443059096264638464)} 0 10
[junit4] 2> 279661 T516 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 279662 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: start
[junit4] 2> 279663 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: enter lock
[junit4] 2> 279665 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: now prepare
[junit4] 2> 279665 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: prepareCommit: flush
[junit4] 2> 279666 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: index before flush
[junit4] 2> 279667 T516 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-516]: qtp648392891-516 startFullFlush
[junit4] 2> 279668 T516 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-516]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279669 T516 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-516]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 6 ]]
[junit4] 2> 279670 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: apply all deletes during flush
[junit4] 2> 279671 T516 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-516]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=0
[junit4] 2> 279671 T516 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-516]: qtp648392891-516 finishFullFlush success=true
[junit4] 2> 279672 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: startCommit(): start
[junit4] 2> 279673 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: startCommit index= changeCount=6
[junit4] 2> 279674 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: done all syncs: []
[junit4] 2> 279675 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: pendingCommit != null
[junit4] 2> 279676 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: wrote segments file "segments_3"
[junit4] 2> 279677 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 279679 T516 C83 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_3,generation=3}
[junit4] 2> 279680 T516 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 279681 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 279682 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.fnm"
[junit4] 2> 279683 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0_Lucene41_0.doc"
[junit4] 2> 279684 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0_Lucene41_0.pos"
[junit4] 2> 279685 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.nvd"
[junit4] 2> 279686 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "segments_2"
[junit4] 2> 279689 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.fdx"
[junit4] 2> 279692 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.si"
[junit4] 2> 279695 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.nvm"
[junit4] 2> 279697 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0_Lucene41_0.tim"
[junit4] 2> 279697 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0.fdt"
[junit4] 2> 279698 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: delete "_0_Lucene41_0.tip"
[junit4] 2> 279699 T516 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-516]: 21 msec to checkpoint
[junit4] 2> 279700 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: commit: done
[junit4] 2> 279701 T516 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-516]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279701 T516 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-516]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 279708 T516 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-516]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279708 T516 C83 oass.SolrIndexSearcher.<init> Opening Searcher@58f16635 main
[junit4] 2> 279709 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@58f16635 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 279710 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 279713 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@58f16635 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 279714 T516 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 279714 T516 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 53
[junit4] 2> 279720 T518 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 279746 T515 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 279748 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: start
[junit4] 2> 279748 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: enter lock
[junit4] 2> 279749 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: now prepare
[junit4] 2> 279750 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: prepareCommit: flush
[junit4] 2> 279751 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: index before flush
[junit4] 2> 279752 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: qtp648392891-515 startFullFlush
[junit4] 2> 279752 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279754 T515 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-515]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=2061, segment=_1, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 7 ]]
[junit4] 2> 279762 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flush postings as segment _1 numDocs=10
[junit4] 2> 279767 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: new segment has 0 deleted docs
[junit4] 2> 279769 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 279770 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushedFiles=[_1.nvm, _1_Lucene41_0.pos, _1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 279774 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushed codec=Lucene42
[junit4] 2> 279776 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushed: segment=_1 ramUsed=0.073 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=8,566.797
[junit4] 2> 279777 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 279778 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: publishFlushedSegment
[junit4] 2> 279778 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=14 packetCount=1 totBytesUsed=1024
[junit4] 2> 279780 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: publish sets newSegment delGen=15 seg=_1(4.5):C10
[junit4] 2> 279781 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: now checkpoint "_1(4.5):C10" [1 segments ; isCommit = false]
[junit4] 2> 279782 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: 0 msec to checkpoint
[junit4] 2> 279783 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: apply all deletes during flush
[junit4] 2> 279784 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: applyDeletes: infos=[_1(4.5):C10] packetCount=1
[junit4] 2> 279785 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: applyDeletes took 1 msec
[junit4] 2> 279786 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=16 packetCount=1
[junit4] 2> 279786 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 279787 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: qtp648392891-515 finishFullFlush success=true
[junit4] 2> 279788 T515 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-515]: findMerges: 1 segments
[junit4] 2> 279790 T515 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-515]: seg=_1(4.5):C10 size=0.001 MB [floored]
[junit4] 2> 279791 T515 C83 oasu.LoggingInfoStream.message [TMP][qtp648392891-515]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 279793 T515 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-515]: now merge
[junit4] 2> 279794 T515 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-515]: index: _1(4.5):C10
[junit4] 2> 279795 T515 C83 oasu.LoggingInfoStream.message [CMS][qtp648392891-515]: no more merges pending; now return
[junit4] 2> 279795 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: startCommit(): start
[junit4] 2> 279797 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: startCommit index=_1(4.5):C10 changeCount=9
[junit4] 2> 279798 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: done all syncs: [_1.fdx, _1_Lucene41_0.pos, _1.nvm, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 279799 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: pendingCommit != null
[junit4] 2> 279800 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: wrote segments file "segments_4"
[junit4] 2> 279801 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: now checkpoint "_1(4.5):C10" [1 segments ; isCommit = true]
[junit4] 2> 279802 T515 C83 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_4,generation=4}
[junit4] 2> 279803 T515 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 279804 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 279805 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: delete "segments_3"
[junit4] 2> 279806 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: 4 msec to checkpoint
[junit4] 2> 279806 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: done
[junit4] 2> 279807 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279808 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 279809 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: flush at getReader
[junit4] 2> 279810 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: qtp648392891-515 startFullFlush
[junit4] 2> 279811 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279811 T515 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-515]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 8 ]]
[junit4] 2> 279812 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: apply all deletes during flush
[junit4] 2> 279813 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: applyDeletes: no deletes; skipping
[junit4] 2> 279814 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=16 packetCount=0
[junit4] 2> 279818 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: return reader version=7 reader=StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)
[junit4] 2> 279819 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: qtp648392891-515 finishFullFlush success=true
[junit4] 2> 279820 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: getReader took 11 msec
[junit4] 2> 279821 T515 C83 oass.SolrIndexSearcher.<init> Opening Searcher@65ef58d7 main
[junit4] 2> 279822 T515 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 279823 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@65ef58d7 main{StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)}
[junit4] 2> 279824 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 279841 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65ef58d7 main{StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)}
[junit4] 2> 279843 T515 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {add=[0 (1443059096357961728), 1 (1443059096362156032), 2 (1443059096364253184), 3 (1443059096365301760), 4 (1443059096367398912), 5 (1443059096368447488), 6 (1443059096369496064), 7 (1443059096371593216), 8 (1443059096372641792), 9 (1443059096373690368)],commit=} 0 114
[junit4] 2> 279852 T517 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=id,score,_docid_&q=*:*&wt=xml&version=2.2} hits=10 status=0 QTime=2
[junit4] 2> 279870 T516 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=id,score,_docid_&q=*:*&wt=javabin&version=2} hits=10 status=0 QTime=1
[junit4] 2> 279879 T510 oas.SolrTestCaseJ4.tearDown ###Ending testStreamingRequest
[junit4] 2> 279952 T510 oas.SolrTestCaseJ4.setUp ###Starting testContentStreamRequest
[junit4] 2> 279964 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279965 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 279966 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279968 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: flush at getReader
[junit4] 2> 279970 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518 startFullFlush
[junit4] 2> 279971 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 279972 T518 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-518]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 9 ]]
[junit4] 2> 279973 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518: flush naked frozen global deletes
[junit4] 2> 279975 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: push deletes 1 deleted queries bytesUsed=36 delGen=18 packetCount=1 totBytesUsed=36
[junit4] 2> 279977 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 279978 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: apply all deletes during flush
[junit4] 2> 279979 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: applyDeletes: infos=[_1(4.5):C10] packetCount=1
[junit4] 2> 279981 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: seg=_1(4.5):C10 segGen=16 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=10 100% deleted
[junit4] 2> 279982 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: applyDeletes took 3 msec
[junit4] 2> 279983 T518 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-518]: now checkpoint "_1(4.5):C10/10" [1 segments ; isCommit = false]
[junit4] 2> 279985 T518 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-518]: 1 msec to checkpoint
[junit4] 2> 279986 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: drop 100% deleted segments: _1(4.5):C10/10
[junit4] 2> 279987 T518 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-518]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 279988 T518 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-518]: 1 msec to checkpoint
[junit4] 2> 279989 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=1
[junit4] 2> 279990 T518 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-518]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 279991 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: return reader version=9 reader=StandardDirectoryReader(segments_4:9:nrt)
[junit4] 2> 279992 T518 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-518]: qtp648392891-518 finishFullFlush success=true
[junit4] 2> 279993 T518 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-518]: getReader took 25 msec
[junit4] 2> 279994 T518 C83 oass.SolrIndexSearcher.<init> Opening Searcher@1d8aba98 realtime
[junit4] 2> 279996 T518 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1443059096600182784)} 0 36
[junit4] 2> 280013 T514 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 280014 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: start
[junit4] 2> 280016 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: enter lock
[junit4] 2> 280017 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: now prepare
[junit4] 2> 280018 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: prepareCommit: flush
[junit4] 2> 280019 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: index before flush
[junit4] 2> 280020 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: qtp648392891-514 startFullFlush
[junit4] 2> 280021 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 280022 T514 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-514]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 10 ]]
[junit4] 2> 280023 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: apply all deletes during flush
[junit4] 2> 280024 T514 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-514]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=9223372036854775807 packetCount=0
[junit4] 2> 280025 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: qtp648392891-514 finishFullFlush success=true
[junit4] 2> 280026 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: startCommit(): start
[junit4] 2> 280027 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: startCommit index= changeCount=12
[junit4] 2> 280028 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: done all syncs: []
[junit4] 2> 280029 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: pendingCommit != null
[junit4] 2> 280031 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: wrote segments file "segments_5"
[junit4] 2> 280033 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 280041 T514 C83 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39e3907d lockFactory=org.apache.lucene.store.NativeFSLockFactory@4c1233d7),segFN=segments_5,generation=5}
[junit4] 2> 280042 T514 C83 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 280043 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 280044 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.fdx"
[junit4] 2> 280051 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1_Lucene41_0.pos"
[junit4] 2> 280052 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 280053 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.nvm"
[junit4] 2> 280054 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1_Lucene41_0.doc"
[junit4] 2> 280055 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: 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> 280056 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.fdt"
[junit4] 2> 280057 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 280058 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.si"
[junit4] 2> 280059 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1_Lucene41_0.tim"
[junit4] 2> 280060 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: 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> 280061 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.nvd"
[junit4] 2> 280062 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 280063 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1_Lucene41_0.tip"
[junit4] 2> 280064 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "_1.fnm"
[junit4] 2> 280065 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: delete "segments_4"
[junit4] 2> 280065 T514 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-514]: 33 msec to checkpoint
[junit4] 2> 280067 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: commit: done
[junit4] 2> 280068 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 280070 T514 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-514]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 280071 T514 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-514]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 280072 T514 C83 oass.SolrIndexSearcher.<init> Opening Searcher@44866277 main
[junit4] 2> 280073 T514 C83 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 280074 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@44866277 main{StandardDirectoryReader(segments_4:9:nrt)}
[junit4] 2> 280075 T521 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 280081 T521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44866277 main{StandardDirectoryReader(segments_4:9:nrt)}
[junit4] 2> 280083 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 280083 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete "_1_Lucene41_0.pos"
[junit4] 2> 280084 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 280085 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 280085 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete pending file _1.fdt
[junit4] 2> 280086 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete "_1.fdt"
[junit4] 2> 280087 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 280087 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 280088 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete pending file _1.nvd
[junit4] 2> 280088 T521 oasu.LoggingInfoStream.message [IFD][searcherExecutor-268-thread-1]: delete "_1.nvd"
[junit4] 2> 280089 T514 C83 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 76
[junit4] 2> 280101 T519 C83 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 280198 T515 C83 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 280200 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: start
[junit4] 2> 280201 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: enter lock
[junit4] 2> 280201 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: commit: now prepare
[junit4] 2> 280202 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: prepareCommit: flush
[junit4] 2> 280203 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: index before flush
[junit4] 2> 280203 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: qtp648392891-515 startFullFlush
[junit4] 2> 280204 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 280206 T515 C83 oasu.LoggingInfoStream.message [DWFC][qtp648392891-515]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=2142, segment=_2, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 11 ]]
[junit4] 2> 280207 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flush postings as segment _2 numDocs=10
[junit4] 2> 280216 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: new segment has 0 deleted docs
[junit4] 2> 280217 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 280220 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushedFiles=[_2_Lucene41_0.pos, _2.nvm, _2_Lucene41_0.tim, _2.nvd, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 280223 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushed codec=Lucene42
[junit4] 2> 280224 T515 C83 oasu.LoggingInfoStream.message [DWPT][qtp648392891-515]: flushed: segment=_2 ramUsed=0.102 MB newFlushedSize(includes docstores)=0.004 MB docs/MB=2,308.622
[junit4] 2> 280225 T515 C83 oasu.LoggingInfoStream.message [DW][qtp648392891-515]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 280226 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: publishFlushedSegment
[junit4] 2> 280226 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=21 packetCount=1 totBytesUsed=1024
[junit4] 2> 280227 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: publish sets newSegment delGen=22 seg=_2(4.5):C10
[junit4] 2> 280227 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: now checkpoint "_2(4.5):C10" [1 segments ; isCommit = false]
[junit4] 2> 280227 T515 C83 oasu.LoggingInfoStream.message [IFD][qtp648392891-515]: 0 msec to checkpoint
[junit4] 2> 280228 T515 C83 oasu.LoggingInfoStream.message [IW][qtp648392891-515]: apply all deletes during flush
[junit4] 2> 280229 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: applyDeletes: infos=[_2(4.5):C10] packetCount=1
[junit4] 2> 280229 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: applyDeletes took 1 msec
[junit4] 2> 280230 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=23 packetCount=1
[junit4] 2> 280230 T515 C83 oasu.LoggingInfoStream.message [BD][qtp648392891-515]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 280230 T515 C83 oasu.LoggingInfoStream.message [DW][qtp6483
[...truncated too long message...]
lose closing DirectUpdateHandler2{commits=54,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=141,cumulative_deletesById=1,cumulative_deletesByQuery=26,cumulative_errors=1}
[junit4] 2> 492839 T510 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 492840 T510 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 492840 T510 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 492847 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: now flush at close waitForMerges=true
[junit4] 2> 492848 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 492849 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: index before flush _12(4.5):C2
[junit4] 2> 492849 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker startFullFlush
[junit4] 2> 492850 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 492851 T510 C84 oasu.LoggingInfoStream.message [DWFC][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 117 ]]
[junit4] 2> 492855 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker finishFullFlush success=true
[junit4] 2> 492859 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: apply all deletes during flush
[junit4] 2> 492862 T510 C84 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 492863 T510 C84 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=216 packetCount=0
[junit4] 2> 492864 T510 C84 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: now merge
[junit4] 2> 492864 T510 C84 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: index: _12(4.5):C2
[junit4] 2> 492865 T510 C84 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: no more merges pending; now return
[junit4] 2> 492866 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: waitForMerges
[junit4] 2> 492867 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: waitForMerges done
[junit4] 2> 492868 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: now call final commit()
[junit4] 2> 492869 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: commit: start
[junit4] 2> 492870 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: commit: enter lock
[junit4] 2> 492870 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: commit: now prepare
[junit4] 2> 492871 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: prepareCommit: flush
[junit4] 2> 492872 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: index before flush _12(4.5):C2
[junit4] 2> 492897 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker startFullFlush
[junit4] 2> 492897 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 492898 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: apply all deletes during flush
[junit4] 2> 492899 T510 C84 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 492900 T510 C84 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@fdc019b minGen=216 packetCount=0
[junit4] 2> 492901 T510 C84 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker finishFullFlush success=true
[junit4] 2> 492902 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: startCommit(): start
[junit4] 2> 492903 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: skip startCommit(): no changes pending
[junit4] 2> 492904 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 492904 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: commit: done
[junit4] 2> 492905 T510 C84 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[A32C48ABC2B4E360]-worker]: at close: _12(4.5):C2
[junit4] 2> 492910 T510 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 492911 T510 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 492911 T510 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index;done=false>>]
[junit4] 2> 492912 T510 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793/index
[junit4] 2> 492913 T510 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793;done=false>>]
[junit4] 2> 492914 T510 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376208390793
[junit4] 2> 492916 T510 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 492969 T510 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=sr_CS, timezone=Asia/Tehran
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=172429568,total=312475648
[junit4] 2> NOTE: All tests run in this JVM: [TestFastInputStream, AnlysisResponseBaseTest, TestCoreAdmin, ClientUtilsTest, ModifiableSolrParamsTest, SolrExampleEmbeddedTest, SolrExampleBinaryTest, SolrQueryTest, TestLBHttpSolrServer, LargeVolumeJettyTest, TestDocumentObjectBinder, NamedListTest, FieldAnalysisResponseTest, LargeVolumeEmbeddedTest, ContentStreamTest, DocumentAnalysisResponseTest, SolrExampleStreamingBinaryTest, MergeIndexesEmbeddedTest, TestJavaBinCodec, LargeVolumeBinaryJettyTest, TestSolrProperties, SolrExceptionTest, CloudSolrServerTest, SolrExampleStreamingTest, SolrExampleXMLTest]
[junit4] Completed in 219.89s, 26 tests, 1 error <<< FAILURES!
[...truncated 69 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:395: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:375: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:194: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:449: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error
Total time: 140 minutes 7 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 702 -
Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/702/
Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testAddDelete
Error Message:
IOException occured when talking to server at: https://127.0.0.1:55300/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:55300/solr/collection1
at __randomizedtesting.SeedInfo.seed([F2078D00D4BA7149:3AE7F00A2512A29F]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
at org.apache.solr.client.solrj.SolrExampleTests.testAddDelete(SolrExampleTests.java:737)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:680)
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 10202 lines...]
[junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest
[junit4] 2> 202234 T474 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 202239 T474 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleJettyTest-1376249694218
[junit4] 2> 202240 T474 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 202241 T474 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 202317 T474 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1] of [SSLv2Hello, SSLv3, TLSv1]
[junit4] 2> 202338 T474 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:55300
[junit4] 2> 202339 T474 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 202339 T474 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 202339 T474 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 202340 T474 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/'
[junit4] 2> 202391 T474 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 202509 T474 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 202514 T474 oasc.CoreContainer.<init> New CoreContainer 286764692
[junit4] 2> 202514 T474 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/]
[junit4] 2> 202516 T474 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 202516 T474 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 202517 T474 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 202517 T474 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 202517 T474 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 202518 T474 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 202518 T474 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 202519 T474 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 202519 T474 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 202519 T474 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 202553 T474 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 202573 T474 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/
[junit4] 2> 202574 T474 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 202585 T484 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1
[junit4] 2> 202586 T484 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 202637 T484 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 202638 T484 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 202639 T484 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 202640 T484 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 202640 T484 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 202641 T484 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 202641 T484 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 202642 T484 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 202642 T484 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 202736 T484 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 202745 T484 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 202955 T484 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 202956 T484 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 202999 T484 oass.IndexSchema.readSchema [collection1] Schema name=example
[junit4] 2> 203922 T484 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 204035 T484 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 204044 T484 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 204086 T484 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 204087 T484 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/
[junit4] 2> 204087 T484 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@53601a4f
[junit4] 2> 204093 T484 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 204094 T484 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 204095 T484 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218
[junit4] 2> 204095 T484 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index/
[junit4] 2> 204096 T484 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index' doesn't exist. Creating new index...
[junit4] 2> 204096 T484 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index
[junit4] 2> 204098 T484 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-245-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@75bf48de
[junit4] 2> 204098 T484 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-245-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 204099 T484 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-245-thread-1]: 0 msec to checkpoint
[junit4] 2> 204099 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: init: create=true
[junit4] 2> 204099 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@61492336
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 204100 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 204100 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 204100 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: index before flush
[junit4] 2> 204101 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: coreLoadExecutor-245-thread-1 startFullFlush
[junit4] 2> 204101 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204101 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: coreLoadExecutor-245-thread-1 finishFullFlush success=true
[junit4] 2> 204102 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: apply all deletes during flush
[junit4] 2> 204102 T484 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-245-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@8a6e020 minGen=9223372036854775807 packetCount=0
[junit4] 2> 204102 T484 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-245-thread-1]: now merge
[junit4] 2> 204103 T484 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-245-thread-1]: index:
[junit4] 2> 204103 T484 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-245-thread-1]: no more merges pending; now return
[junit4] 2> 204103 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: waitForMerges
[junit4] 2> 204103 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: waitForMerges done
[junit4] 2> 204104 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: now call final commit()
[junit4] 2> 204104 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: start
[junit4] 2> 204104 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: enter lock
[junit4] 2> 204105 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: now prepare
[junit4] 2> 204105 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: prepareCommit: flush
[junit4] 2> 204105 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: index before flush
[junit4] 2> 204106 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: coreLoadExecutor-245-thread-1 startFullFlush
[junit4] 2> 204106 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204106 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: apply all deletes during flush
[junit4] 2> 204107 T484 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-245-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@8a6e020 minGen=9223372036854775807 packetCount=0
[junit4] 2> 204107 T484 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-245-thread-1]: coreLoadExecutor-245-thread-1 finishFullFlush success=true
[junit4] 2> 204107 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: startCommit(): start
[junit4] 2> 204112 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: startCommit index= changeCount=1
[junit4] 2> 204113 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: done all syncs: []
[junit4] 2> 204113 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: pendingCommit != null
[junit4] 2> 204113 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 204114 T484 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-245-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 204114 T484 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_1,generation=1}
[junit4] 2> 204114 T484 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 204115 T484 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-245-thread-1]: 1 msec to checkpoint
[junit4] 2> 204116 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: commit: done
[junit4] 2> 204116 T484 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-245-thread-1]: at close:
[junit4] 2> 204117 T484 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 204117 T484 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 204118 T484 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 204118 T484 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 204118 T484 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 204132 T484 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 204133 T484 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 204134 T484 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 204135 T484 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 204135 T484 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 204136 T484 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 204137 T484 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 204138 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 204138 T484 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 204138 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 204139 T484 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 204139 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 204140 T484 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 204141 T484 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 204142 T484 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 204143 T484 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 204144 T484 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 204144 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 204148 T484 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 204148 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 204149 T484 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 204149 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 204150 T484 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 204150 T484 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 204150 T484 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 204167 T484 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 204169 T484 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 204171 T484 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 204179 T484 oass.SolrIndexSearcher.<init> Opening Searcher@617de0a8 main
[junit4] 2> 204181 T484 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 204181 T484 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 204182 T484 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 204182 T484 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> 204183 T484 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 204184 T484 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 204239 T484 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 204239 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@617de0a8 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> ASYNC NEW_CORE C77 name=collection1 org.apache.solr.core.SolrCore@2ac28d29
[junit4] 2> 204241 T485 C77 oasc.SolrCore.execute [collection1] webapp=null path=null params={event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml&distrib=false} hits=0 status=0 QTime=1
[junit4] 2> 204241 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204242 T485 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 204242 T485 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 204245 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@617de0a8 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 204254 T484 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 204257 T474 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 204257 T474 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 204258 T474 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#55300
[junit4] 2> 204271 T474 oas.SolrTestCaseJ4.setUp ###Starting testMultiContentStreamRequest
[junit4] 2> 204271 T474 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 204350 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@75bf48de
[junit4] 2> 204351 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: init: load commit "segments_1"
[junit4] 2> 204351 T479 C77 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_1,generation=1}
[junit4] 2> 204352 T479 C77 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 204353 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 204353 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: 0 msec to checkpoint
[junit4] 2> 204354 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: init: create=false
[junit4] 2> 204354 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@70bd61d4
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 204357 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: flush at getReader
[junit4] 2> 204357 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: qtp1415138589-479 startFullFlush
[junit4] 2> 204358 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204358 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: qtp1415138589-479: flush naked frozen global deletes
[junit4] 2> 204360 T479 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-479]: push deletes 1 deleted queries bytesUsed=32 delGen=1 packetCount=1 totBytesUsed=32
[junit4] 2> 204363 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 204366 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: apply all deletes during flush
[junit4] 2> 204366 T479 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-479]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=9223372036854775807 packetCount=1
[junit4] 2> 204366 T479 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-479]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204367 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 204367 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: qtp1415138589-479 finishFullFlush success=true
[junit4] 2> 204368 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: getReader took 11 msec
[junit4] 2> 204368 T479 C77 oass.SolrIndexSearcher.<init> Opening Searcher@4641439f realtime
[junit4] 2> 204369 T479 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1443102401573683200)} 0 23
[junit4] 2> 204375 T480 C77 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 204376 T480 C77 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 204377 T480 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-480]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204377 T480 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-480]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 204378 T480 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-480]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204378 T480 C77 oass.SolrIndexSearcher.<init> Opening Searcher@170e3e70 main
[junit4] 2> 204380 T480 C77 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 204381 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@170e3e70 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 204381 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204385 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@170e3e70 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 204386 T480 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4] 2> 204393 T481 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1
[junit4] 2> 204426 T482 C77 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 204427 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: start
[junit4] 2> 204427 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: enter lock
[junit4] 2> 204427 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: now prepare
[junit4] 2> 204428 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: prepareCommit: flush
[junit4] 2> 204429 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: index before flush
[junit4] 2> 204429 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 startFullFlush
[junit4] 2> 204431 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=5 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204434 T482 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-482]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 4 deleted terms (unique count=4) bytesUsed=699, segment=_0, aborting=false, numDocsInRAM=5, deleteQueue=DWDQ: [ generation: 1 ]]
[junit4] 2> 204436 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flush postings as segment _0 numDocs=5
[junit4] 2> 204443 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: new segment has 0 deleted docs
[junit4] 2> 204444 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 204444 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushedFiles=[_0_Lucene41_0.pay, _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> 204445 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushed codec=Lucene42
[junit4] 2> 204446 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushed: segment=_0 ramUsed=0.115 MB newFlushedSize(includes docstores)=0.007 MB docs/MB=728.785
[junit4] 2> 204446 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 204447 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: publishFlushedSegment
[junit4] 2> 204448 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: push deletes 5 deleted terms (unique count=5) bytesUsed=1024 delGen=3 packetCount=1 totBytesUsed=1024
[junit4] 2> 204448 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: publish sets newSegment delGen=4 seg=_0(4.5):C5
[junit4] 2> 204449 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: now checkpoint "_0(4.5):C5" [1 segments ; isCommit = false]
[junit4] 2> 204450 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: 0 msec to checkpoint
[junit4] 2> 204450 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: apply all deletes during flush
[junit4] 2> 204451 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes: infos=[_0(4.5):C5] packetCount=1
[junit4] 2> 204451 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes took 0 msec
[junit4] 2> 204452 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=5 packetCount=1
[junit4] 2> 204452 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204453 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 finishFullFlush success=true
[junit4] 2> 204453 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: findMerges: 1 segments
[junit4] 2> 204454 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: seg=_0(4.5):C5 size=0.007 MB [floored]
[junit4] 2> 204455 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 204455 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: now merge
[junit4] 2> 204456 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: index: _0(4.5):C5
[junit4] 2> 204456 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: no more merges pending; now return
[junit4] 2> 204457 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: startCommit(): start
[junit4] 2> 204457 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: startCommit index=_0(4.5):C5 changeCount=3
[junit4] 2> 204458 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: done all syncs: [_0_Lucene41_0.pay, _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> 204458 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: pendingCommit != null
[junit4] 2> 204459 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: wrote segments file "segments_2"
[junit4] 2> 204460 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: now checkpoint "_0(4.5):C5" [1 segments ; isCommit = true]
[junit4] 2> 204460 T482 C77 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_2,generation=2}
[junit4] 2> 204461 T482 C77 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 204461 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 204462 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: delete "segments_1"
[junit4] 2> 204462 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: 2 msec to checkpoint
[junit4] 2> 204463 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: done
[junit4] 2> 204464 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204464 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 204465 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: flush at getReader
[junit4] 2> 204465 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 startFullFlush
[junit4] 2> 204466 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204466 T482 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-482]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 204467 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: apply all deletes during flush
[junit4] 2> 204468 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes: no deletes; skipping
[junit4] 2> 204469 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=5 packetCount=0
[junit4] 2> 204472 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C5)
[junit4] 2> 204472 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 finishFullFlush success=true
[junit4] 2> 204473 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: getReader took 8 msec
[junit4] 2> 204473 T482 C77 oass.SolrIndexSearcher.<init> Opening Searcher@4e7016ff main
[junit4] 2> 204474 T482 C77 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 204474 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@4e7016ff main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C5)}
[junit4] 2> 204475 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204479 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e7016ff main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C5)}
[junit4] 2> 204480 T482 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&echoParams=ALL&commit=true&a=?&wt=javabin&version=2&softCommit=false} {add=[SP2514N (1443102401639743488), 6H500F0 (1443102401644986368), TWINX2048-3200PRO (1443102401648132096), VS1GB400C3 (1443102401651277824), VDBDB1A16 (1443102401654423552)],commit=} 0 71
[junit4] 2> 204487 T483 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=5 status=0 QTime=1
[junit4] 2> 204490 T474 oas.SolrTestCaseJ4.tearDown ###Ending testMultiContentStreamRequest
[junit4] 2> 204508 T474 oas.SolrTestCaseJ4.setUp ###Starting testFaceting
[junit4] 2> 204514 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204514 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 204515 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204515 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: flush at getReader
[junit4] 2> 204516 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: qtp1415138589-478 startFullFlush
[junit4] 2> 204516 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204517 T478 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-478]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 3 ]]
[junit4] 2> 204517 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: qtp1415138589-478: flush naked frozen global deletes
[junit4] 2> 204518 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: push deletes 1 deleted queries bytesUsed=32 delGen=7 packetCount=1 totBytesUsed=32
[junit4] 2> 204519 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 204520 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: apply all deletes during flush
[junit4] 2> 204520 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: applyDeletes: infos=[_0(4.5):C5] packetCount=1
[junit4] 2> 204524 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: seg=_0(4.5):C5 segGen=5 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=5 100% deleted
[junit4] 2> 204524 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: applyDeletes took 4 msec
[junit4] 2> 204525 T478 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-478]: now checkpoint "_0(4.5):C5/5" [1 segments ; isCommit = false]
[junit4] 2> 204526 T478 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-478]: 0 msec to checkpoint
[junit4] 2> 204526 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: drop 100% deleted segments: _0(4.5):C5/5
[junit4] 2> 204527 T478 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-478]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 204527 T478 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-478]: 0 msec to checkpoint
[junit4] 2> 204528 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=9223372036854775807 packetCount=1
[junit4] 2> 204528 T478 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-478]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204529 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 204529 T478 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-478]: qtp1415138589-478 finishFullFlush success=true
[junit4] 2> 204530 T478 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-478]: getReader took 15 msec
[junit4] 2> 204531 T478 C77 oass.SolrIndexSearcher.<init> Opening Searcher@60532b8 realtime
[junit4] 2> 204531 T478 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1443102401746698240)} 0 19
[junit4] 2> 204537 T479 C77 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 204537 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: start
[junit4] 2> 204538 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: enter lock
[junit4] 2> 204538 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: now prepare
[junit4] 2> 204539 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: prepareCommit: flush
[junit4] 2> 204539 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: index before flush
[junit4] 2> 204540 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: qtp1415138589-479 startFullFlush
[junit4] 2> 204540 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204541 T479 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-479]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 4 ]]
[junit4] 2> 204541 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: apply all deletes during flush
[junit4] 2> 204542 T479 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-479]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=9223372036854775807 packetCount=0
[junit4] 2> 204542 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: qtp1415138589-479 finishFullFlush success=true
[junit4] 2> 204543 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: startCommit(): start
[junit4] 2> 204543 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: startCommit index= changeCount=6
[junit4] 2> 204544 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: done all syncs: []
[junit4] 2> 204544 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: pendingCommit != null
[junit4] 2> 204545 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: wrote segments file "segments_3"
[junit4] 2> 204546 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 204546 T479 C77 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_3,generation=3}
[junit4] 2> 204547 T479 C77 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 204547 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 204548 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0_Lucene41_0.pay"
[junit4] 2> 204549 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: unable to remove file "_0_Lucene41_0.pay": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pay" is still open: cannot delete; Will re-try later.
[junit4] 2> 204549 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.fnm"
[junit4] 2> 204550 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0_Lucene41_0.doc"
[junit4] 2> 204550 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: 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> 204551 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0_Lucene41_0.pos"
[junit4] 2> 204551 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: 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> 204552 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.nvd"
[junit4] 2> 204552 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 204553 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "segments_2"
[junit4] 2> 204554 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.fdx"
[junit4] 2> 204557 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.si"
[junit4] 2> 204559 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.nvm"
[junit4] 2> 204560 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0_Lucene41_0.tim"
[junit4] 2> 204561 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: 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> 204561 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0.fdt"
[junit4] 2> 204562 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 204562 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: delete "_0_Lucene41_0.tip"
[junit4] 2> 204563 T479 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-479]: 17 msec to checkpoint
[junit4] 2> 204563 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: commit: done
[junit4] 2> 204564 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204567 T479 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-479]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 204568 T479 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-479]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204568 T479 C77 oass.SolrIndexSearcher.<init> Opening Searcher@4a15d117 main
[junit4] 2> 204569 T479 C77 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 204569 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@4a15d117 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 204570 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204573 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a15d117 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 204574 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0_Lucene41_0.pay
[junit4] 2> 204574 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0_Lucene41_0.pay"
[junit4] 2> 204575 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 204575 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 204575 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 204576 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0_Lucene41_0.pos"
[junit4] 2> 204576 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0.nvd
[junit4] 2> 204576 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0.nvd"
[junit4] 2> 204577 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 204577 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 204577 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _0.fdt
[junit4] 2> 204578 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_0.fdt"
[junit4] 2> 204578 T479 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 41
[junit4] 2> 204583 T480 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 204600 T481 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1 (1443102401829535744), 2 (1443102401833730048), 3 (1443102401834778624), 4 (1443102401835827200), 5 (1443102401835827201), 6 (1443102401836875776), 7 (1443102401836875777), 8 (1443102401836875778), 9 (1443102401837924352), 10 (1443102401837924353)]} 0 11
[junit4] 2> 204606 T482 C77 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 204607 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: start
[junit4] 2> 204607 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: enter lock
[junit4] 2> 204610 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: now prepare
[junit4] 2> 204610 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: prepareCommit: flush
[junit4] 2> 204610 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: index before flush
[junit4] 2> 204611 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 startFullFlush
[junit4] 2> 204611 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204612 T482 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-482]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=1486, segment=_1, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 204612 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flush postings as segment _1 numDocs=10
[junit4] 2> 204615 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: new segment has 0 deleted docs
[junit4] 2> 204615 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 204615 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushedFiles=[_1.nvm, _1_Lucene41_0.pos, _1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 204616 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushed codec=Lucene42
[junit4] 2> 204617 T482 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-482]: flushed: segment=_1 ramUsed=0.081 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=7,670.636
[junit4] 2> 204617 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 204618 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: publishFlushedSegment
[junit4] 2> 204618 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
[junit4] 2> 204619 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: publish sets newSegment delGen=11 seg=_1(4.5):C10
[junit4] 2> 204619 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: now checkpoint "_1(4.5):C10" [1 segments ; isCommit = false]
[junit4] 2> 204620 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: 0 msec to checkpoint
[junit4] 2> 204620 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: apply all deletes during flush
[junit4] 2> 204621 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes: infos=[_1(4.5):C10] packetCount=1
[junit4] 2> 204621 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes took 0 msec
[junit4] 2> 204621 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=12 packetCount=1
[junit4] 2> 204623 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204628 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 finishFullFlush success=true
[junit4] 2> 204629 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: findMerges: 1 segments
[junit4] 2> 204630 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: seg=_1(4.5):C10 size=0.001 MB [floored]
[junit4] 2> 204630 T482 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-482]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 204633 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: now merge
[junit4] 2> 204633 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: index: _1(4.5):C10
[junit4] 2> 204634 T482 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-482]: no more merges pending; now return
[junit4] 2> 204634 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: startCommit(): start
[junit4] 2> 204634 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: startCommit index=_1(4.5):C10 changeCount=9
[junit4] 2> 204635 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: done all syncs: [_1.fdx, _1_Lucene41_0.pos, _1.nvm, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 204636 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: pendingCommit != null
[junit4] 2> 204636 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: wrote segments file "segments_4"
[junit4] 2> 204637 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: now checkpoint "_1(4.5):C10" [1 segments ; isCommit = true]
[junit4] 2> 204637 T482 C77 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_4,generation=4}
[junit4] 2> 204638 T482 C77 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 204638 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 204638 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: delete "segments_3"
[junit4] 2> 204639 T482 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-482]: 2 msec to checkpoint
[junit4] 2> 204639 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: commit: done
[junit4] 2> 204640 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204640 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 204641 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: flush at getReader
[junit4] 2> 204641 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 startFullFlush
[junit4] 2> 204641 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204642 T482 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-482]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 6 ]]
[junit4] 2> 204642 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: apply all deletes during flush
[junit4] 2> 204642 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: applyDeletes: no deletes; skipping
[junit4] 2> 204643 T482 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-482]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=12 packetCount=0
[junit4] 2> 204645 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: return reader version=7 reader=StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)
[junit4] 2> 204645 T482 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-482]: qtp1415138589-482 finishFullFlush success=true
[junit4] 2> 204646 T482 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-482]: getReader took 5 msec
[junit4] 2> 204646 T482 C77 oass.SolrIndexSearcher.<init> Opening Searcher@52c62074 main
[junit4] 2> 204647 T482 C77 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 204647 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@52c62074 main{StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)}
[junit4] 2> 204647 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204650 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@52c62074 main{StandardDirectoryReader(segments_4:7:nrt _1(4.5):C10)}
[junit4] 2> 204651 T482 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 45
[junit4] 2> 204662 T483 C77 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=features,memSize=4564,tindexSize=44,time=1,phase1=1,nTerms=4,bigTerms=2,termInstances=4,uses=0}
[junit4] 2> 204662 T483 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&facet.field=features&wt=javabin&version=2&rows=0} hits=10 status=0 QTime=2
[junit4] 2> 204668 T478 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&facet.field=features&wt=javabin&fq=features:two&version=2&rows=0} hits=5 status=0 QTime=1
[junit4] 2> 204675 T479 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=4&q=*:*&facet.field=features&wt=javabin&fq=features:two&version=2&rows=0} hits=5 status=0 QTime=3
[junit4] 2> 204680 T480 C77 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=-1&q=*:*&facet.field=features&wt=javabin&fq=features:two&version=2&rows=0} hits=5 status=0 QTime=1
[junit4] 2> 204682 T474 oas.SolrTestCaseJ4.tearDown ###Ending testFaceting
[junit4] 2> 204701 T474 oas.SolrTestCaseJ4.setUp ###Starting testRealtimeGet
[junit4] 2> 204706 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204706 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 204707 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204708 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: flush at getReader
[junit4] 2> 204708 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: qtp1415138589-481 startFullFlush
[junit4] 2> 204708 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204709 T481 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-481]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 7 ]]
[junit4] 2> 204709 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: qtp1415138589-481: flush naked frozen global deletes
[junit4] 2> 204710 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: push deletes 1 deleted queries bytesUsed=32 delGen=14 packetCount=1 totBytesUsed=32
[junit4] 2> 204710 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 204711 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: apply all deletes during flush
[junit4] 2> 204711 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: applyDeletes: infos=[_1(4.5):C10] packetCount=1
[junit4] 2> 204712 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: seg=_1(4.5):C10 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=10 100% deleted
[junit4] 2> 204712 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: applyDeletes took 1 msec
[junit4] 2> 204713 T481 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-481]: now checkpoint "_1(4.5):C10/10" [1 segments ; isCommit = false]
[junit4] 2> 204713 T481 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-481]: 0 msec to checkpoint
[junit4] 2> 204714 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: drop 100% deleted segments: _1(4.5):C10/10
[junit4] 2> 204714 T481 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-481]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 204715 T481 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-481]: 1 msec to checkpoint
[junit4] 2> 204716 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=9223372036854775807 packetCount=1
[junit4] 2> 204717 T481 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-481]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204718 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: return reader version=9 reader=StandardDirectoryReader(segments_4:9:nrt)
[junit4] 2> 204718 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: qtp1415138589-481 finishFullFlush success=true
[junit4] 2> 204720 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: getReader took 12 msec
[junit4] 2> 204724 T481 C77 oass.SolrIndexSearcher.<init> Opening Searcher@aa85638 realtime
[junit4] 2> 204725 T481 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1443102401948024832)} 0 21
[junit4] 2> 204731 T482 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[DOCID (1443102401975287808)]} 0 2
[junit4] 2> 204735 T483 C77 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 204735 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: start
[junit4] 2> 204735 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: enter lock
[junit4] 2> 204736 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: now prepare
[junit4] 2> 204736 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: prepareCommit: flush
[junit4] 2> 204739 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: index before flush
[junit4] 2> 204739 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: qtp1415138589-483 startFullFlush
[junit4] 2> 204740 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204740 T483 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-483]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 8 ]]
[junit4] 2> 204741 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: flush postings as segment _2 numDocs=1
[junit4] 2> 204743 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: new segment has 0 deleted docs
[junit4] 2> 204744 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 204744 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: flushedFiles=[_2_Lucene41_0.pos, _2.nvm, _2_Lucene41_0.tim, _2.nvd, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 204745 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: flushed codec=Lucene42
[junit4] 2> 204745 T483 C77 oasu.LoggingInfoStream.message [DWPT][qtp1415138589-483]: flushed: segment=_2 ramUsed=0.079 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,083.24
[junit4] 2> 204746 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 204746 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: publishFlushedSegment
[junit4] 2> 204747 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=16 packetCount=1 totBytesUsed=1024
[junit4] 2> 204747 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: publish sets newSegment delGen=17 seg=_2(4.5):C1
[junit4] 2> 204747 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: now checkpoint "_2(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 204748 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 0 msec to checkpoint
[junit4] 2> 204748 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: apply all deletes during flush
[junit4] 2> 204749 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: applyDeletes: infos=[_2(4.5):C1] packetCount=1
[junit4] 2> 204749 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: applyDeletes took 0 msec
[junit4] 2> 204749 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=18 packetCount=1
[junit4] 2> 204750 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 204750 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: qtp1415138589-483 finishFullFlush success=true
[junit4] 2> 204751 T483 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-483]: findMerges: 1 segments
[junit4] 2> 204751 T483 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-483]: seg=_2(4.5):C1 size=0.001 MB [floored]
[junit4] 2> 204752 T483 C77 oasu.LoggingInfoStream.message [TMP][qtp1415138589-483]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 204753 T483 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-483]: now merge
[junit4] 2> 204753 T483 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-483]: index: _2(4.5):C1
[junit4] 2> 204754 T483 C77 oasu.LoggingInfoStream.message [CMS][qtp1415138589-483]: no more merges pending; now return
[junit4] 2> 204755 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: startCommit(): start
[junit4] 2> 204758 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: startCommit index=_2(4.5):C1 changeCount=14
[junit4] 2> 204760 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: done all syncs: [_2.si, _2_Lucene41_0.pos, _2_Lucene41_0.tim, _2.nvm, _2.nvd, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 204760 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: pendingCommit != null
[junit4] 2> 204761 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: wrote segments file "segments_5"
[junit4] 2> 204761 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: now checkpoint "_2(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 204762 T483 C77 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6cb2b9ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@72402ecb),segFN=segments_5,generation=5}
[junit4] 2> 204762 T483 C77 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 204763 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 204763 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.fdx"
[junit4] 2> 204764 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.pos"
[junit4] 2> 204764 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 204765 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.nvm"
[junit4] 2> 204765 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.doc"
[junit4] 2> 204766 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 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> 204766 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.fdt"
[junit4] 2> 204767 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 204767 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.si"
[junit4] 2> 204768 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.tim"
[junit4] 2> 204768 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 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> 204769 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.nvd"
[junit4] 2> 204769 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 204769 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.tip"
[junit4] 2> 204770 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.fnm"
[junit4] 2> 204770 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "segments_4"
[junit4] 2> 204771 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 9 msec to checkpoint
[junit4] 2> 204771 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: commit: done
[junit4] 2> 204772 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204772 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 204772 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: flush at getReader
[junit4] 2> 204773 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: qtp1415138589-483 startFullFlush
[junit4] 2> 204773 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204774 T483 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-483]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 9 ]]
[junit4] 2> 204775 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: apply all deletes during flush
[junit4] 2> 204775 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: applyDeletes: no deletes; skipping
[junit4] 2> 204776 T483 C77 oasu.LoggingInfoStream.message [BD][qtp1415138589-483]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=18 packetCount=0
[junit4] 2> 204777 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: return reader version=11 reader=StandardDirectoryReader(segments_5:11:nrt _2(4.5):C1)
[junit4] 2> 204778 T483 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-483]: qtp1415138589-483 finishFullFlush success=true
[junit4] 2> 204778 T483 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-483]: getReader took 6 msec
[junit4] 2> 204779 T483 C77 oass.SolrIndexSearcher.<init> Opening Searcher@48719726 main
[junit4] 2> 204779 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 204780 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.pos"
[junit4] 2> 204780 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 204780 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 204781 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.doc"
[junit4] 2> 204782 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 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> 204782 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete pending file _1.fdt
[junit4] 2> 204782 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.fdt"
[junit4] 2> 204783 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 204783 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 204784 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1_Lucene41_0.tim"
[junit4] 2> 204784 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: 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> 204784 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete pending file _1.nvd
[junit4] 2> 204785 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: delete "_1.nvd"
[junit4] 2> 204786 T483 C77 oasu.LoggingInfoStream.message [IFD][qtp1415138589-483]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 204786 T483 C77 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 204786 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@48719726 main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C1)}
[junit4] 2> 204792 T485 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 204795 T485 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@48719726 main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C1)}
[junit4] 2> 204796 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 204797 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_1_Lucene41_0.pos"
[junit4] 2> 204797 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 204797 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 204798 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _1.fdt
[junit4] 2> 204798 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_1.fdt"
[junit4] 2> 204798 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 204799 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 204799 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete pending file _1.nvd
[junit4] 2> 204799 T485 oasu.LoggingInfoStream.message [IFD][searcherExecutor-246-thread-1]: delete "_1.nvd"
[junit4] 2> 204800 T483 C77 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 65
[junit4] 2> 204812 T479 C77 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> 204822 T480 C77 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> 204827 T474 oas.SolrTestCaseJ4.tearDown ###Ending testRealtimeGet
[junit4] 2> 204839 T474 oas.SolrTestCaseJ4.setUp ###Starting testChineseDefaults
[junit4] 2> 204849 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204850 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 204850 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204851 T481 C77 oasu.LoggingInfoStream.message [IW][qtp1415138589-481]: flush at getReader
[junit4] 2> 204851 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: qtp1415138589-481 startFullFlush
[junit4] 2> 204852 T481 C77 oasu.LoggingInfoStream.message [DW][qtp1415138589-481]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 204852 T481 C77 oasu.LoggingInfoStream.message [DWFC][qtp1415138589-481]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 10 ]]
[junit
[...truncated too long message...]
rectUpdateHandler2{commits=55,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=128,cumulative_deletesById=1,cumulative_deletesByQuery=26,cumulative_errors=1}
[junit4] 2> 415249 T474 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 415250 T474 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 415250 T474 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 415263 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: now flush at close waitForMerges=true
[junit4] 2> 415264 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 415264 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: index before flush _12(4.5):C10
[junit4] 2> 415265 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker startFullFlush
[junit4] 2> 415269 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 415271 T474 C78 oasu.LoggingInfoStream.message [DWFC][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 119 ]]
[junit4] 2> 415272 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker finishFullFlush success=true
[junit4] 2> 415272 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: apply all deletes during flush
[junit4] 2> 415273 T474 C78 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 415273 T474 C78 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=219 packetCount=0
[junit4] 2> 415274 T474 C78 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: now merge
[junit4] 2> 415274 T474 C78 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: index: _12(4.5):C10
[junit4] 2> 415275 T474 C78 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: no more merges pending; now return
[junit4] 2> 415275 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: waitForMerges
[junit4] 2> 415276 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: waitForMerges done
[junit4] 2> 415276 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: now call final commit()
[junit4] 2> 415277 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: commit: start
[junit4] 2> 415277 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: commit: enter lock
[junit4] 2> 415277 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: commit: now prepare
[junit4] 2> 415278 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: prepareCommit: flush
[junit4] 2> 415278 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: index before flush _12(4.5):C10
[junit4] 2> 415279 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker startFullFlush
[junit4] 2> 415281 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 415282 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: apply all deletes during flush
[junit4] 2> 415282 T474 C78 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 415283 T474 C78 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@207f7d58 minGen=219 packetCount=0
[junit4] 2> 415283 T474 C78 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker finishFullFlush success=true
[junit4] 2> 415284 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: startCommit(): start
[junit4] 2> 415284 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: skip startCommit(): no changes pending
[junit4] 2> 415285 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 415285 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: commit: done
[junit4] 2> 415286 T474 C78 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[F2078D00D4BA7149]-worker]: at close: _12(4.5):C10
[junit4] 2> 415288 T474 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 415289 T474 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 415289 T474 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index;done=false>>]
[junit4] 2> 415290 T474 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218/index
[junit4] 2> 415290 T474 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218;done=false>>]
[junit4] 2> 415291 T474 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1376249694218
[junit4] 2> 415291 T474 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 415347 T474 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=es_AR, timezone=US/Pacific
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Apple Inc. 1.6.0_51 (64-bit)/cpus=2,threads=1,free=64900776,total=219414528
[junit4] 2> NOTE: All tests run in this JVM: [TestBatchUpdate, MergeIndexesEmbeddedTest, FacetFieldTest, AnlysisResponseBaseTest, ClientUtilsTest, ModifiableSolrParamsTest, TestLBHttpSolrServer, JettyWebappTest, LargeVolumeJettyTest, FieldAnalysisResponseTest, SolrExampleStreamingTest, CloudSolrServerTest, SolrExceptionTest, SolrExampleBinaryTest, BasicHttpSolrServerTest, TestJavaBinCodec, SolrDocumentTest, TestCoreAdmin, TestHash, LargeVolumeEmbeddedTest, SolrExampleJettyTest]
[junit4] Completed in 213.24s, 27 tests, 1 error <<< FAILURES!
[...truncated 81 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:395: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:375: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:194: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:449: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error
Total time: 116 minutes 41 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure