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/09 02:43:23 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 715 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/715/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.SolrExampleXMLTest.testUnicode
Error Message:
IOException occured when talking to server at: https://127.0.0.1:51795/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:51795/solr/collection1
at __randomizedtesting.SeedInfo.seed([4DD7135D3AD14350:541BA757986B92A7]: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:68)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:54)
at org.apache.solr.client.solrj.SolrExampleTests.testUnicode(SolrExampleTests.java:375)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java: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 10658 lines...]
[junit4] Suite: org.apache.solr.client.solrj.SolrExampleXMLTest
[junit4] 2> 46935 T29 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 46937 T29 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleXMLTest-1376008454943
[junit4] 2> 46939 T29 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 47993 T29 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 49263 T29 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 49417 T29 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:?????
[junit4] 2> 49697 T29 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 49699 T29 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 49700 T29 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 49701 T29 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/'
[junit4] 2> 49810 T29 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 50125 T29 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 50230 T29 oasc.CoreContainer.<init> New CoreContainer 1187253017
[junit4] 2> 50243 T29 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/]
[junit4] 2> 50403 T29 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 50404 T29 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 50405 T29 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 50405 T29 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 50406 T29 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 50407 T29 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 50408 T29 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 50408 T29 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 50409 T29 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 50410 T29 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 50466 T29 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 50525 T29 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/
[junit4] 2> 50528 T29 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 50541 T41 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1
[junit4] 2> 50550 T41 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 50881 T41 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 50882 T41 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 50883 T41 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 50884 T41 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 50885 T41 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 50886 T41 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 50887 T41 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 50902 T41 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 50904 T41 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 51316 T41 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 51323 T41 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 51537 T41 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 51538 T41 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 51712 T41 oass.IndexSchema.readSchema [collection1] Schema name=example
[junit4] 2> 53230 T41 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 53275 T41 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 53316 T41 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 53544 T41 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 53545 T41 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/
[junit4] 2> 53558 T41 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6437d88e
[junit4] 2> 53571 T41 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 53572 T41 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 53593 T41 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943
[junit4] 2> 53604 T41 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index/
[junit4] 2> 53605 T41 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index' doesn't exist. Creating new index...
[junit4] 2> 53606 T41 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index
[junit4] 2> 53610 T41 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-32-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@22a71ac
[junit4] 2> 53611 T41 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-32-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 53612 T41 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-32-thread-1]: 0 msec to checkpoint
[junit4] 2> 53615 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: init: create=true
[junit4] 2> 53623 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=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@308cd450
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 53624 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 53625 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 53625 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: index before flush
[junit4] 2> 53626 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: coreLoadExecutor-32-thread-1 startFullFlush
[junit4] 2> 53626 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 53627 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: coreLoadExecutor-32-thread-1 finishFullFlush success=true
[junit4] 2> 53628 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: apply all deletes during flush
[junit4] 2> 53629 T41 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-32-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@6dc6e916 minGen=9223372036854775807 packetCount=0
[junit4] 2> 53630 T41 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-32-thread-1]: now merge
[junit4] 2> 53644 T41 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-32-thread-1]: index:
[junit4] 2> 53645 T41 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-32-thread-1]: no more merges pending; now return
[junit4] 2> 53646 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: waitForMerges
[junit4] 2> 53646 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: waitForMerges done
[junit4] 2> 53647 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: now call final commit()
[junit4] 2> 53648 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: start
[junit4] 2> 53648 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: enter lock
[junit4] 2> 53649 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: now prepare
[junit4] 2> 53649 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: prepareCommit: flush
[junit4] 2> 53650 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: index before flush
[junit4] 2> 53650 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: coreLoadExecutor-32-thread-1 startFullFlush
[junit4] 2> 53651 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 53652 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: apply all deletes during flush
[junit4] 2> 53652 T41 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-32-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@6dc6e916 minGen=9223372036854775807 packetCount=0
[junit4] 2> 53653 T41 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-32-thread-1]: coreLoadExecutor-32-thread-1 finishFullFlush success=true
[junit4] 2> 53653 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: startCommit(): start
[junit4] 2> 53654 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: startCommit index= changeCount=1
[junit4] 2> 53655 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: done all syncs: []
[junit4] 2> 53656 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: pendingCommit != null
[junit4] 2> 53663 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 53664 T41 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-32-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 53665 T41 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_1,generation=1}
[junit4] 2> 53665 T41 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 53666 T41 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-32-thread-1]: 2 msec to checkpoint
[junit4] 2> 53667 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: commit: done
[junit4] 2> 53671 T41 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-32-thread-1]: at close:
[junit4] 2> 53684 T41 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 53685 T41 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 53686 T41 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 53687 T41 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 53688 T41 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 53810 T41 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 53813 T41 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 53815 T41 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 53818 T41 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 53824 T41 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 53830 T41 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 53834 T41 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 53835 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 53836 T41 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 53837 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 53838 T41 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 53839 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 53840 T41 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 53898 T41 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 53901 T41 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 53902 T41 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 53904 T41 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 53904 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 53905 T41 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 53906 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 53911 T41 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 53913 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 53914 T41 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 53916 T41 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 53917 T41 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 53934 T41 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 53940 T41 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 53948 T41 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 54046 T41 oass.SolrIndexSearcher.<init> Opening Searcher@374eb126 main
[junit4] 2> 54049 T41 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 54050 T41 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 54051 T41 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 54052 T41 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> 54053 T41 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 54057 T41 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 54204 T41 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 54206 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@374eb126 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> ASYNC NEW_CORE C11 name=collection1 org.apache.solr.core.SolrCore@7a117b86
[junit4] 2> 54216 T42 C11 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=10
[junit4] 2> 54217 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 54217 T42 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 54218 T42 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 54222 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@374eb126 main{StandardDirectoryReader(segments_1:1)}
[junit4] 2> 54268 T41 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 54272 T29 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 54273 T29 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 54274 T29 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#51795
[junit4] 2> 54309 T29 oas.SolrTestCaseJ4.setUp ###Starting testPivotFacetsMissing
[junit4] 2> 54391 T29 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C12 name=collection1 org.apache.solr.core.SolrCore@7a117b86
[junit4] 2> 56724 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@22a71ac
[junit4] 2> 56727 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: init: load commit "segments_1"
[junit4] 2> 56728 T40 C12 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_1,generation=1}
[junit4] 2> 56732 T40 C12 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 56762 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 56767 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: 5 msec to checkpoint
[junit4] 2> 56768 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: init: create=false
[junit4] 2> 56771 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=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@6b103fcf
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 56790 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: flush at getReader
[junit4] 2> 56793 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40 startFullFlush
[junit4] 2> 56808 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 56811 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40: flush naked frozen global deletes
[junit4] 2> 56812 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: push deletes 1 deleted queries bytesUsed=32 delGen=1 packetCount=1 totBytesUsed=32
[junit4] 2> 56813 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 56814 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: apply all deletes during flush
[junit4] 2> 56815 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=9223372036854775807 packetCount=1
[junit4] 2> 56816 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 56817 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 56818 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40 finishFullFlush success=true
[junit4] 2> 56818 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: getReader took 28 msec
[junit4] 2> 56819 T40 C12 oass.SolrIndexSearcher.<init> Opening Searcher@3983fc21 realtime
[junit4] 2> 56821 T40 C12 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1442849451903287296)} 0 135
[junit4] 2> 57461 T37 C12 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 57463 T37 C12 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 57464 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 57466 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 57481 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 57484 T37 C12 oass.SolrIndexSearcher.<init> Opening Searcher@75be93a7 main
[junit4] 2> 57487 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@75be93a7 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 57489 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 57499 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@75be93a7 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 57503 T37 C12 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 57514 T37 C12 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> 57534 T38 C12 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 57611 T39 C12 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[1 (1442849452791431168), 2 (1442849452802965504), 3 (1442849452806111232), 4 (1442849452808208384), 5 (1442849452811354112), 6 (1442849452814499840), 7 (1442849452821839872), 8 (1442849452829179904), 9 (1442849452831277056), 10 (1442849452834422784), ... (12 adds)]} 0 49
[junit4] 2> 57672 T36 C12 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 57674 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: start
[junit4] 2> 57677 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: enter lock
[junit4] 2> 57679 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: now prepare
[junit4] 2> 57680 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: prepareCommit: flush
[junit4] 2> 57681 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: index before flush
[junit4] 2> 57681 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 startFullFlush
[junit4] 2> 57683 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=12 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 57684 T36 C12 oasu.LoggingInfoStream.message [DWFC][qtp822092765-36]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 11 deleted terms (unique count=11) bytesUsed=1818, segment=_0, aborting=false, numDocsInRAM=12, deleteQueue=DWDQ: [ generation: 1 ]]
[junit4] 2> 57685 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: flush postings as segment _0 numDocs=12
[junit4] 2> 57694 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: new segment has 0 deleted docs
[junit4] 2> 57695 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 57695 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: 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> 57696 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: flushed codec=Lucene42
[junit4] 2> 57698 T36 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-36]: flushed: segment=_0 ramUsed=0.082 MB newFlushedSize(includes docstores)=0.002 MB docs/MB=7,315.647
[junit4] 2> 57700 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 57720 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: publishFlushedSegment
[junit4] 2> 57730 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: push deletes 12 deleted terms (unique count=12) bytesUsed=1024 delGen=3 packetCount=1 totBytesUsed=1024
[junit4] 2> 57730 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: publish sets newSegment delGen=4 seg=_0(5.0):C12
[junit4] 2> 57732 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: now checkpoint "_0(5.0):C12" [1 segments ; isCommit = false]
[junit4] 2> 57732 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: 0 msec to checkpoint
[junit4] 2> 57733 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: apply all deletes during flush
[junit4] 2> 57734 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: applyDeletes: infos=[_0(5.0):C12] packetCount=1
[junit4] 2> 57734 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: applyDeletes took 0 msec
[junit4] 2> 57735 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=5 packetCount=1
[junit4] 2> 57736 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 57736 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 finishFullFlush success=true
[junit4] 2> 57737 T36 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-36]: findMerges: 1 segments
[junit4] 2> 57738 T36 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-36]: seg=_0(5.0):C12 size=0.001 MB [floored]
[junit4] 2> 57742 T36 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-36]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 57743 T36 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-36]: now merge
[junit4] 2> 57743 T36 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-36]: index: _0(5.0):C12
[junit4] 2> 57745 T36 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-36]: no more merges pending; now return
[junit4] 2> 57745 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: startCommit(): start
[junit4] 2> 57746 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: startCommit index=_0(5.0):C12 changeCount=3
[junit4] 2> 57747 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: 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> 57748 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: pendingCommit != null
[junit4] 2> 57748 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: wrote segments file "segments_2"
[junit4] 2> 57749 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: now checkpoint "_0(5.0):C12" [1 segments ; isCommit = true]
[junit4] 2> 57750 T36 C12 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_2,generation=2}
[junit4] 2> 57751 T36 C12 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 57752 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 57752 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: delete "segments_1"
[junit4] 2> 57753 T36 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: 3 msec to checkpoint
[junit4] 2> 57754 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: commit: done
[junit4] 2> 57755 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 57755 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 57756 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: flush at getReader
[junit4] 2> 57757 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 startFullFlush
[junit4] 2> 57757 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 57758 T36 C12 oasu.LoggingInfoStream.message [DWFC][qtp822092765-36]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 57759 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: apply all deletes during flush
[junit4] 2> 57759 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: applyDeletes: no deletes; skipping
[junit4] 2> 57760 T36 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=5 packetCount=0
[junit4] 2> 57763 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)
[junit4] 2> 57764 T36 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 finishFullFlush success=true
[junit4] 2> 57765 T36 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: getReader took 9 msec
[junit4] 2> 57767 T36 C12 oass.SolrIndexSearcher.<init> Opening Searcher@76520c83 main
[junit4] 2> 57769 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@76520c83 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)}
[junit4] 2> 57769 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 57775 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@76520c83 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C12)}
[junit4] 2> 57779 T36 C12 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 57780 T36 C12 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 108
[junit4] 2> 58089 T38 C12 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=features,memSize=4521,tindexSize=43,time=26,phase1=26,nTerms=2,bigTerms=2,termInstances=0,uses=0}
[junit4] 2> 58241 T38 C12 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=cat,memSize=4515,tindexSize=41,time=0,phase1=0,nTerms=2,bigTerms=2,termInstances=0,uses=0}
[junit4] 2> 58265 T38 C12 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet.missing=true&facet=true&facet.mincount=0&q=*:*&wt=xml&facet.pivot=features,cat&facet.pivot=cat,features&facet.pivot=features,cat,inStock&version=2.2&rows=0} hits=12 status=0 QTime=458
[junit4] 2> 58433 T35 C12 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&wt=xml&fq={!tag%3Dmytag}-(features:bbb+AND+cat:a+AND+inStock:true)&facet.pivot={!ex%3Dmytag+key%3Dmykey}features,cat&version=2.2&rows=0} hits=11 status=0 QTime=85
[junit4] 2> 58441 T29 oas.SolrTestCaseJ4.tearDown ###Ending testPivotFacetsMissing
[junit4] 2> 58511 T29 oas.SolrTestCaseJ4.setUp ###Starting testRealtimeGet
[junit4] 2> 58521 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58523 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 58524 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58525 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: flush at getReader
[junit4] 2> 58527 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40 startFullFlush
[junit4] 2> 58528 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58529 T40 C12 oasu.LoggingInfoStream.message [DWFC][qtp822092765-40]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 3 ]]
[junit4] 2> 58530 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40: flush naked frozen global deletes
[junit4] 2> 58532 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: push deletes 1 deleted queries bytesUsed=32 delGen=7 packetCount=1 totBytesUsed=32
[junit4] 2> 58533 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 58534 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: apply all deletes during flush
[junit4] 2> 58535 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: applyDeletes: infos=[_0(5.0):C12] packetCount=1
[junit4] 2> 58538 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: seg=_0(5.0):C12 segGen=5 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=12 100% deleted
[junit4] 2> 58539 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: applyDeletes took 4 msec
[junit4] 2> 58540 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: now checkpoint "_0(5.0):C12/12" [1 segments ; isCommit = false]
[junit4] 2> 58541 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: 1 msec to checkpoint
[junit4] 2> 58542 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: drop 100% deleted segments: _0(5.0):C12/12
[junit4] 2> 58543 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 58544 T40 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-40]: 1 msec to checkpoint
[junit4] 2> 58545 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=9223372036854775807 packetCount=1
[junit4] 2> 58546 T40 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-40]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 58548 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 58548 T40 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-40]: qtp822092765-40 finishFullFlush success=true
[junit4] 2> 58549 T40 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-40]: getReader took 24 msec
[junit4] 2> 58551 T40 C12 oass.SolrIndexSearcher.<init> Opening Searcher@55379dff realtime
[junit4] 2> 58552 T40 C12 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1442849453793869824)} 0 33
[junit4] 2> 58587 T36 C12 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[DOCID (1442849453856784384)]} 0 9
[junit4] 2> 58614 T37 C12 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 58620 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: start
[junit4] 2> 58621 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: enter lock
[junit4] 2> 58622 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: now prepare
[junit4] 2> 58624 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: prepareCommit: flush
[junit4] 2> 58624 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: index before flush
[junit4] 2> 58625 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37 startFullFlush
[junit4] 2> 58626 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58627 T37 C12 oasu.LoggingInfoStream.message [DWFC][qtp822092765-37]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 4 ]]
[junit4] 2> 58629 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: flush postings as segment _1 numDocs=1
[junit4] 2> 58642 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: new segment has 0 deleted docs
[junit4] 2> 58643 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 58644 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: 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> 58645 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: flushed codec=Lucene42
[junit4] 2> 58647 T37 C12 oasu.LoggingInfoStream.message [DWPT][qtp822092765-37]: flushed: segment=_1 ramUsed=0.079 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,084.36
[junit4] 2> 58649 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 58651 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: publishFlushedSegment
[junit4] 2> 58652 T37 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=9 packetCount=1 totBytesUsed=1024
[junit4] 2> 58653 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: publish sets newSegment delGen=10 seg=_1(5.0):C1
[junit4] 2> 58654 T37 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: now checkpoint "_1(5.0):C1" [1 segments ; isCommit = false]
[junit4] 2> 58655 T37 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 1 msec to checkpoint
[junit4] 2> 58656 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: apply all deletes during flush
[junit4] 2> 58657 T37 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: applyDeletes: infos=[_1(5.0):C1] packetCount=1
[junit4] 2> 58658 T37 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: applyDeletes took 1 msec
[junit4] 2> 58659 T37 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=11 packetCount=1
[junit4] 2> 58660 T37 C12 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 58661 T37 C12 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37 finishFullFlush success=true
[junit4] 2> 58662 T37 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-37]: findMerges: 1 segments
[junit4] 2> 58679 T37 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-37]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 58682 T37 C12 oasu.LoggingInfoStream.message [TMP][qtp822092765-37]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 58684 T37 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-37]: now merge
[junit4] 2> 58685 T37 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-37]: index: _1(5.0):C1
[junit4] 2> 58686 T37 C12 oasu.LoggingInfoStream.message [CMS][qtp822092765-37]: no more merges pending; now return
[junit4] 2> 58687 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: startCommit(): start
[junit4] 2> 58688 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: startCommit index=_1(5.0):C1 changeCount=8
[junit4] 2> 58704 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: 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> 58705 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: pendingCommit != null
[junit4] 2> 58732 T37 C12 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: wrote segments file "segments_3"
[junit4] 2> 58733 T37 C12 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: now checkpoint "_1(5.0):C1" [1 segments ; isCommit = true]
[junit4] 2> 58735 T37 C12 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_3,generation=3}
[junit4] 2> 58735 T37 C12 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> ASYNC NEW_CORE C13 name=collection1 org.apache.solr.core.SolrCore@7a117b86
[junit4] 2> 58755 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 58757 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.fnm"
[junit4] 2> 58758 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.doc"
[junit4] 2> 58759 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58759 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.pos"
[junit4] 2> 58760 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58760 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.nvd"
[junit4] 2> 58761 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 58762 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "segments_2"
[junit4] 2> 58763 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.fdx"
[junit4] 2> 58763 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.si"
[junit4] 2> 58764 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.nvm"
[junit4] 2> 58765 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.tim"
[junit4] 2> 58765 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58766 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.fdt"
[junit4] 2> 58767 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 58767 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.tip"
[junit4] 2> 58768 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 34 msec to checkpoint
[junit4] 2> 58773 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: commit: done
[junit4] 2> 58775 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58776 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 58777 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: flush at getReader
[junit4] 2> 58777 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37 startFullFlush
[junit4] 2> 58778 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58779 T37 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-37]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 58780 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: apply all deletes during flush
[junit4] 2> 58780 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: applyDeletes: no deletes; skipping
[junit4] 2> 58781 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=11 packetCount=0
[junit4] 2> 58784 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)
[junit4] 2> 58785 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37 finishFullFlush success=true
[junit4] 2> 58786 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: getReader took 9 msec
[junit4] 2> 58787 T37 C13 oass.SolrIndexSearcher.<init> Opening Searcher@198cc898 main
[junit4] 2> 58788 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 58788 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.doc"
[junit4] 2> 58789 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58790 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 58790 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.pos"
[junit4] 2> 58791 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58792 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete pending file _0.nvd
[junit4] 2> 58792 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.nvd"
[junit4] 2> 58793 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 58794 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 58794 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0_Lucene41_0.tim"
[junit4] 2> 58795 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 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> 58796 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete pending file _0.fdt
[junit4] 2> 58796 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: delete "_0.fdt"
[junit4] 2> 58797 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 58798 T37 C13 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 58798 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@198cc898 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 58799 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 58806 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@198cc898 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 58820 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 58821 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 58821 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 58822 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_0_Lucene41_0.pos"
[junit4] 2> 58822 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _0.nvd
[junit4] 2> 58823 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_0.nvd"
[junit4] 2> 58823 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 58824 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 58824 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _0.fdt
[junit4] 2> 58825 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_0.fdt"
[junit4] 2> 58825 T37 C13 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 211
[junit4] 2> 58849 T35 C13 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=6
[junit4] 2> 58882 T40 C13 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=1
[junit4] 2> 58888 T29 oas.SolrTestCaseJ4.tearDown ###Ending testRealtimeGet
[junit4] 2> 58949 T29 oas.SolrTestCaseJ4.setUp ###Starting testFaceting
[junit4] 2> 58964 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58965 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 58965 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58966 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: flush at getReader
[junit4] 2> 58967 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 startFullFlush
[junit4] 2> 58967 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 58968 T36 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-36]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 6 ]]
[junit4] 2> 58969 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36: flush naked frozen global deletes
[junit4] 2> 58970 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: push deletes 1 deleted queries bytesUsed=32 delGen=13 packetCount=1 totBytesUsed=32
[junit4] 2> 58971 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 58977 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: apply all deletes during flush
[junit4] 2> 58978 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: applyDeletes: infos=[_1(5.0):C1] packetCount=1
[junit4] 2> 58987 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: seg=_1(5.0):C1 segGen=11 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
[junit4] 2> 58988 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: applyDeletes took 10 msec
[junit4] 2> 58989 T36 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: now checkpoint "_1(5.0):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 58989 T36 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: 0 msec to checkpoint
[junit4] 2> 58990 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: drop 100% deleted segments: _1(5.0):C1/1
[junit4] 2> 58991 T36 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 58991 T36 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-36]: 0 msec to checkpoint
[junit4] 2> 58992 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=9223372036854775807 packetCount=1
[junit4] 2> 58993 T36 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-36]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 58993 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
[junit4] 2> 58994 T36 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-36]: qtp822092765-36 finishFullFlush success=true
[junit4] 2> 58995 T36 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-36]: getReader took 29 msec
[junit4] 2> 58995 T36 C13 oass.SolrIndexSearcher.<init> Opening Searcher@170282ca realtime
[junit4] 2> 58996 T36 C13 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1442849454258388992)} 0 35
[junit4] 2> 59035 T39 C13 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 59036 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: start
[junit4] 2> 59036 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: enter lock
[junit4] 2> 59037 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: now prepare
[junit4] 2> 59038 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: prepareCommit: flush
[junit4] 2> 59038 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: index before flush
[junit4] 2> 59039 T39 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-39]: qtp822092765-39 startFullFlush
[junit4] 2> 59039 T39 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-39]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59040 T39 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-39]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 7 ]]
[junit4] 2> 59041 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: apply all deletes during flush
[junit4] 2> 59041 T39 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-39]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=9223372036854775807 packetCount=0
[junit4] 2> 59042 T39 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-39]: qtp822092765-39 finishFullFlush success=true
[junit4] 2> 59043 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: startCommit(): start
[junit4] 2> 59043 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: startCommit index= changeCount=11
[junit4] 2> 59052 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: done all syncs: []
[junit4] 2> 59053 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: pendingCommit != null
[junit4] 2> 59054 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: wrote segments file "segments_4"
[junit4] 2> 59055 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 59056 T39 C13 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_4,generation=4}
[junit4] 2> 59056 T39 C13 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 59057 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 59058 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.fdx"
[junit4] 2> 59058 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1_Lucene41_0.pos"
[junit4] 2> 59059 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: 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> 59060 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.nvm"
[junit4] 2> 59061 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1_Lucene41_0.doc"
[junit4] 2> 59077 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: 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> 59078 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.fdt"
[junit4] 2> 59079 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 59079 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.si"
[junit4] 2> 59080 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1_Lucene41_0.tim"
[junit4] 2> 59081 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: 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> 59081 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.nvd"
[junit4] 2> 59082 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 59083 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1_Lucene41_0.tip"
[junit4] 2> 59084 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "_1.fnm"
[junit4] 2> 59092 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: delete "segments_3"
[junit4] 2> 59093 T39 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-39]: 38 msec to checkpoint
[junit4] 2> 59094 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: commit: done
[junit4] 2> 59095 T39 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-39]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59096 T39 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-39]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 59097 T39 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-39]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59099 T39 C13 oass.SolrIndexSearcher.<init> Opening Searcher@37b11602 main
[junit4] 2> 59105 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@37b11602 main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 59106 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 59106 T39 C13 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 59113 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@37b11602 main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 59118 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 59119 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_1_Lucene41_0.pos"
[junit4] 2> 59119 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 59120 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 59121 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _1.fdt
[junit4] 2> 59121 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_1.fdt"
[junit4] 2> 59122 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 59124 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 59125 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete pending file _1.nvd
[junit4] 2> 59125 T42 oasu.LoggingInfoStream.message [IFD][searcherExecutor-33-thread-1]: delete "_1.nvd"
[junit4] 2> 59126 T39 C13 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 91
[junit4] 2> 59135 T37 C13 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 59180 T38 C13 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[1 (1442849454459715584), 2 (1442849454473347072), 3 (1442849454475444224), 4 (1442849454476492800), 5 (1442849454478589952), 6 (1442849454479638528), 7 (1442849454481735680), 8 (1442849454482784256), 9 (1442849454483832832), 10 (1442849454485929984)]} 0 33
[junit4] 2> 59194 T35 C13 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 59195 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: start
[junit4] 2> 59196 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: enter lock
[junit4] 2> 59196 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: now prepare
[junit4] 2> 59197 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: prepareCommit: flush
[junit4] 2> 59197 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: index before flush
[junit4] 2> 59198 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: qtp822092765-35 startFullFlush
[junit4] 2> 59199 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59200 T35 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-35]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=1486, segment=_2, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 8 ]]
[junit4] 2> 59201 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: flush postings as segment _2 numDocs=10
[junit4] 2> 59217 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: new segment has 0 deleted docs
[junit4] 2> 59219 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 59220 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: 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> 59220 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: flushed codec=Lucene42
[junit4] 2> 59222 T35 C13 oasu.LoggingInfoStream.message [DWPT][qtp822092765-35]: flushed: segment=_2 ramUsed=0.081 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=7,715.791
[junit4] 2> 59223 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 59224 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: publishFlushedSegment
[junit4] 2> 59224 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=16 packetCount=1 totBytesUsed=1024
[junit4] 2> 59225 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: publish sets newSegment delGen=17 seg=_2(5.0):C10
[junit4] 2> 59226 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: now checkpoint "_2(5.0):C10" [1 segments ; isCommit = false]
[junit4] 2> 59226 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: 0 msec to checkpoint
[junit4] 2> 59227 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: apply all deletes during flush
[junit4] 2> 59228 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: applyDeletes: infos=[_2(5.0):C10] packetCount=1
[junit4] 2> 59232 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: applyDeletes took 0 msec
[junit4] 2> 59233 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=18 packetCount=1
[junit4] 2> 59234 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 59234 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: qtp822092765-35 finishFullFlush success=true
[junit4] 2> 59234 T35 C13 oasu.LoggingInfoStream.message [TMP][qtp822092765-35]: findMerges: 1 segments
[junit4] 2> 59235 T35 C13 oasu.LoggingInfoStream.message [TMP][qtp822092765-35]: seg=_2(5.0):C10 size=0.001 MB [floored]
[junit4] 2> 59236 T35 C13 oasu.LoggingInfoStream.message [TMP][qtp822092765-35]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 59236 T35 C13 oasu.LoggingInfoStream.message [CMS][qtp822092765-35]: now merge
[junit4] 2> 59236 T35 C13 oasu.LoggingInfoStream.message [CMS][qtp822092765-35]: index: _2(5.0):C10
[junit4] 2> 59237 T35 C13 oasu.LoggingInfoStream.message [CMS][qtp822092765-35]: no more merges pending; now return
[junit4] 2> 59237 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: startCommit(): start
[junit4] 2> 59238 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: startCommit index=_2(5.0):C10 changeCount=14
[junit4] 2> 59239 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: 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> 59239 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: pendingCommit != null
[junit4] 2> 59240 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: wrote segments file "segments_5"
[junit4] 2> 59240 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: now checkpoint "_2(5.0):C10" [1 segments ; isCommit = true]
[junit4] 2> 59240 T35 C13 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@245eca5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@8fdfa17),segFN=segments_5,generation=5}
[junit4] 2> 59241 T35 C13 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 59241 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 59242 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: delete "segments_4"
[junit4] 2> 59242 T35 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-35]: 2 msec to checkpoint
[junit4] 2> 59243 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: commit: done
[junit4] 2> 59243 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59244 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 59244 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: flush at getReader
[junit4] 2> 59245 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: qtp822092765-35 startFullFlush
[junit4] 2> 59245 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59246 T35 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-35]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 9 ]]
[junit4] 2> 59247 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: apply all deletes during flush
[junit4] 2> 59248 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: applyDeletes: no deletes; skipping
[junit4] 2> 59248 T35 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-35]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=18 packetCount=0
[junit4] 2> 59261 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: return reader version=11 reader=StandardDirectoryReader(segments_5:11:nrt _2(5.0):C10)
[junit4] 2> 59262 T35 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-35]: qtp822092765-35 finishFullFlush success=true
[junit4] 2> 59262 T35 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-35]: getReader took 18 msec
[junit4] 2> 59263 T35 C13 oass.SolrIndexSearcher.<init> Opening Searcher@7f480b93 main
[junit4] 2> 59263 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@7f480b93 main{StandardDirectoryReader(segments_5:11:nrt _2(5.0):C10)}
[junit4] 2> 59264 T42 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 59268 T42 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7f480b93 main{StandardDirectoryReader(segments_5:11:nrt _2(5.0):C10)}
[junit4] 2> 59270 T35 C13 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 59273 T35 C13 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 79
[junit4] 2> 59288 T36 C13 oasr.UnInvertedField.<init> UnInverted multi-valued field {field=features,memSize=4564,tindexSize=44,time=1,phase1=0,nTerms=4,bigTerms=2,termInstances=4,uses=0}
[junit4] 2> 59298 T36 C13 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&facet.field=features&wt=xml&version=2.2&rows=0} hits=10 status=0 QTime=12
[junit4] 2> 59355 T39 C13 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=0&q=*:*&facet.field=features&wt=xml&fq=features:two&version=2.2&rows=0} hits=5 status=0 QTime=13
[junit4] 2> 59395 T39 C13 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=4&q=*:*&facet.field=features&wt=xml&fq=features:two&version=2.2&rows=0} hits=5 status=0 QTime=1
[junit4] 2> 59441 T37 C13 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={facet=true&facet.mincount=-1&q=*:*&facet.field=features&wt=xml&fq=features:two&version=2.2&rows=0} hits=5 status=0 QTime=1
[junit4] 2> 59457 T29 oas.SolrTestCaseJ4.tearDown ###Ending testFaceting
[junit4] 2> 59506 T29 oas.SolrTestCaseJ4.setUp ###Starting testUpdateRequestWithParameters
[junit4] 2> 59507 T29 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 59676 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59676 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 59677 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59678 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: flush at getReader
[junit4] 2> 59678 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37 startFullFlush
[junit4] 2> 59698 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 59699 T37 C13 oasu.LoggingInfoStream.message [DWFC][qtp822092765-37]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 10 ]]
[junit4] 2> 59700 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: qtp822092765-37: flush naked frozen global deletes
[junit4] 2> 59701 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: push deletes 1 deleted queries bytesUsed=32 delGen=20 packetCount=1 totBytesUsed=32
[junit4] 2> 59701 T37 C13 oasu.LoggingInfoStream.message [DW][qtp822092765-37]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 59702 T37 C13 oasu.LoggingInfoStream.message [IW][qtp822092765-37]: apply all deletes during flush
[junit4] 2> 59703 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: applyDeletes: infos=[_2(5.0):C10] packetCount=1
[junit4] 2> 59705 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: seg=_2(5.0):C10 segGen=18 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=10 100% deleted
[junit4] 2> 59705 T37 C13 oasu.LoggingInfoStream.message [BD][qtp822092765-37]: applyDeletes took 2 msec
[junit4] 2> 59706 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: now checkpoint "_2(5.0):C10/10" [1 segments ; isCommit = false]
[junit4] 2> 59707 T37 C13 oasu.LoggingInfoStream.message [IFD][qtp822092765-37]: 0 m
[...truncated too long message...]
s.facet=inStock&stats.field=val_pi&stats=true&q=*:*&wt=xml&version=2.2&rows=0} hits=10 status=0 QTime=97
[junit4] 2> 275770 T29 oas.SolrTestCaseJ4.tearDown ###Ending testStatistics
[junit4] 2> 275797 T29 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1187253017
[junit4] 2> 275799 T29 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@7a117b86
[junit4] 2> 275851 T29 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=57,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=5,cumulative_deletesByQuery=25,cumulative_errors=1}
[junit4] 2> 275853 T29 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 275853 T29 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 275853 T29 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 275882 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: now flush at close waitForMerges=true
[junit4] 2> 275883 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 275895 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: index before flush _12(5.0):C10
[junit4] 2> 275896 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker startFullFlush
[junit4] 2> 275896 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 275897 T29 C22 oasu.LoggingInfoStream.message [DWFC][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=null, aborting=false, numDocsInRAM=0, deleteQueue=DWDQ: [ generation: 120 ]]
[junit4] 2> 275897 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker finishFullFlush success=true
[junit4] 2> 275898 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: apply all deletes during flush
[junit4] 2> 275898 T29 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 275899 T29 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=220 packetCount=0
[junit4] 2> 275899 T29 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: now merge
[junit4] 2> 275900 T29 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: index: _12(5.0):C10
[junit4] 2> 275900 T29 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: no more merges pending; now return
[junit4] 2> 275900 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: waitForMerges
[junit4] 2> 275901 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: waitForMerges done
[junit4] 2> 275901 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: now call final commit()
[junit4] 2> 275902 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: commit: start
[junit4] 2> 275902 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: commit: enter lock
[junit4] 2> 275903 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: commit: now prepare
[junit4] 2> 275903 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: prepareCommit: flush
[junit4] 2> 275904 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: index before flush _12(5.0):C10
[junit4] 2> 275904 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker startFullFlush
[junit4] 2> 275905 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 275909 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: apply all deletes during flush
[junit4] 2> 275909 T29 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 275909 T29 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@77cd65f2 minGen=220 packetCount=0
[junit4] 2> 275910 T29 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker finishFullFlush success=true
[junit4] 2> 275910 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: startCommit(): start
[junit4] 2> 275911 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: skip startCommit(): no changes pending
[junit4] 2> 275911 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 275912 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: commit: done
[junit4] 2> 275912 T29 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[4DD7135D3AD14350]-worker]: at close: _12(5.0):C10
[junit4] 2> 275930 T29 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 275932 T29 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 275932 T29 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943 [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943;done=false>>]
[junit4] 2> 275933 T29 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943
[junit4] 2> 275933 T29 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index [CachedDir<<refCount=0;path=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index;done=false>>]
[junit4] 2> 275934 T29 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1376008454943/index
[junit4] 2> 275935 T29 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 275997 T29 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=th_TH_TH_#u-nu-thai, timezone=America/Santa_Isabel
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=55747640,total=92864512
[junit4] 2> NOTE: All tests run in this JVM: [TestSolrProperties, TestJavaBinCodec, TestSpellCheckResponse, SolrExampleXMLTest]
[junit4] Completed in 229.28s, 26 tests, 1 error <<< FAILURES!
[...truncated 135 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:389: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:369: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:194: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:449: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1230: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:873: There were test failures: 46 suites, 272 tests, 1 error
Total time: 121 minutes 37 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure