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/31 14:30:45 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 784 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/784/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testLukeHandler
Error Message:
IOException occured when talking to server at: https://127.0.0.1:51972/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:51972/solr/collection1
at __randomizedtesting.SeedInfo.seed([DF8D4B9857AD7D31:1BED5A3ADC8A7A59]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.client.solrj.SolrExampleTests.testLukeHandler(SolrExampleTests.java:782)
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 10812 lines...]
[junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest
[junit4] 2> 73534 T170 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 73535 T170 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleJettyTest-1377951792604
[junit4] 2> 73536 T170 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 73537 T170 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 73546 T170 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 73552 T170 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:51972
[junit4] 2> 73553 T170 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 73553 T170 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 73554 T170 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 73555 T170 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/'
[junit4] 2> 73602 T170 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 73716 T170 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 73718 T170 oasc.CoreContainer.<init> New CoreContainer 1459784621
[junit4] 2> 73718 T170 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/]
[junit4] 2> 73721 T170 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 73721 T170 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 73722 T170 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 73722 T170 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 73723 T170 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 73723 T170 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 73724 T170 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 73724 T170 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 73725 T170 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 73725 T170 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 73733 T170 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 73733 T170 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 73742 T170 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 73754 T170 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/
[junit4] 2> 73755 T170 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 73757 T180 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1
[junit4] 2> 73758 T180 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 73799 T180 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 73800 T180 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 73801 T180 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 73802 T180 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 73802 T180 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 73803 T180 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 73803 T180 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 73804 T180 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 73804 T180 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 73948 T180 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 73963 T180 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 74098 T180 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 74099 T180 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 74132 T180 oass.IndexSchema.readSchema [null] Schema name=example
[junit4] 2> 75374 T180 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 75401 T180 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 75412 T180 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 75534 T180 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 75535 T180 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/
[junit4] 2> 75535 T180 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@10e73e0
[junit4] 2> 75536 T180 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 75537 T180 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 75555 T180 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604
[junit4] 2> 75556 T180 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index/
[junit4] 2> 75556 T180 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index' doesn't exist. Creating new index...
[junit4] 2> 75557 T180 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index
[junit4] 2> 75562 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@2a43c26f
[junit4] 2> 75566 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 75566 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 0 msec to checkpoint
[junit4] 2> 75567 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: init: create=true
[junit4] 2> 75567 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@46921b16
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 75568 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 75571 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 75571 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: index before flush
[junit4] 2> 75572 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 75573 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75573 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 75574 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 75574 T180 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@2230658c minGen=9223372036854775807 packetCount=0
[junit4] 2> 75575 T180 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: now merge
[junit4] 2> 75575 T180 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: index:
[junit4] 2> 75575 T180 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: no more merges pending; now return
[junit4] 2> 75576 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: waitForMerges
[junit4] 2> 75576 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: waitForMerges done
[junit4] 2> 75578 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: now call final commit()
[junit4] 2> 75578 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: start
[junit4] 2> 75579 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: enter lock
[junit4] 2> 75579 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: now prepare
[junit4] 2> 75580 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: prepareCommit: flush
[junit4] 2> 75580 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: index before flush
[junit4] 2> 75581 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 75581 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75582 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 75582 T180 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@2230658c minGen=9223372036854775807 packetCount=0
[junit4] 2> 75582 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 75583 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: startCommit(): start
[junit4] 2> 75583 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: startCommit index= changeCount=1
[junit4] 2> 75584 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: done all syncs: []
[junit4] 2> 75585 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: pendingCommit != null
[junit4] 2> 75585 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 75586 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 75586 T180 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_1,generation=1}
[junit4] 2> 75587 T180 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 75587 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 1 msec to checkpoint
[junit4] 2> 75588 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: done
[junit4] 2> 75588 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: at close:
[junit4] 2> 75590 T180 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 75590 T180 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 75591 T180 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 75591 T180 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 75591 T180 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 75609 T180 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 75611 T180 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 75612 T180 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 75614 T180 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 75615 T180 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 75616 T180 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 75617 T180 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 75618 T180 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 75618 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 75619 T180 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 75620 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 75621 T180 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 75621 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 75622 T180 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 75624 T180 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 75626 T180 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 75627 T180 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 75629 T180 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 75629 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 75630 T180 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 75630 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 75631 T180 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 75631 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 75632 T180 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 75632 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 75634 T180 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 75634 T180 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 75635 T180 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 75663 T180 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 75666 T180 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 75669 T180 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 75687 T180 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 75688 T180 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 75691 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@2a43c26f
[junit4] 2> 75691 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: load commit "segments_1"
[junit4] 2> 75692 T180 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_1,generation=1}
[junit4] 2> 75693 T180 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 75693 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 75694 T180 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 0 msec to checkpoint
[junit4] 2> 75694 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: init: create=false
[junit4] 2> 75695 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@f0bbc9
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 75696 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: flush at getReader
[junit4] 2> 75696 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 75696 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75697 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 75698 T180 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=9223372036854775807 packetCount=0
[junit4] 2> 75699 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 75699 T180 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 75700 T180 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: getReader took 5 msec
[junit4] 2> 75701 T180 oass.SolrIndexSearcher.<init> Opening Searcher@279f1fa9 main
[junit4] 2> 75702 T180 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 75703 T180 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> 75704 T180 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 75706 T180 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 75775 T180 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 75776 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@279f1fa9 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C18 name=collection1 org.apache.solr.core.SolrCore@ce9c2fd
[junit4] 2> 75779 T181 C18 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=2
[junit4] 2> 75779 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 75784 T181 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 75784 T181 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 75788 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@279f1fa9 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 75791 T180 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 75794 T170 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 75794 T170 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 75795 T170 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#51972
[junit4] 2> 75815 T170 oas.SolrTestCaseJ4.setUp ###Starting testUpdateRequestWithParameters
[junit4] 2> 75816 T170 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 75926 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75927 T175 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-175]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 75928 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75929 T175 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-175]: flush at getReader
[junit4] 2> 75930 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: qtp1082217009-175 startFullFlush
[junit4] 2> 75931 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75932 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: qtp1082217009-175: flush naked frozen global deletes
[junit4] 2> 75934 T175 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-175]: push deletes 1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
[junit4] 2> 75935 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 75935 T175 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-175]: apply all deletes during flush
[junit4] 2> 75937 T175 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-175]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=9223372036854775807 packetCount=1
[junit4] 2> 75938 T175 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-175]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 75939 T175 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-175]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 75940 T175 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-175]: qtp1082217009-175 finishFullFlush success=true
[junit4] 2> 75941 T175 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-175]: getReader took 12 msec
[junit4] 2> 75943 T175 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444887181378191360)} 0 28
[junit4] 2> 75954 T176 C18 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 75956 T176 C18 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 75967 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75969 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 75969 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 75971 T176 C18 oass.SolrIndexSearcher.<init> Opening Searcher@40e4c71e main
[junit4] 2> 75972 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@40e4c71e main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 75973 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 75980 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40e4c71e main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 75984 T176 C18 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 75985 T176 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 31
[junit4] 2> 76021 T178 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={overwrite=false&wt=javabin&version=2} {add=[id1 (1444887181462077440)]} 0 25
[junit4] 2> 76032 T179 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={overwrite=false&wt=javabin&version=2} {add=[id1 (1444887181497729024)]} 0 2
[junit4] 2> 76060 T174 C18 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 76068 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: start
[junit4] 2> 76070 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: enter lock
[junit4] 2> 76070 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: now prepare
[junit4] 2> 76071 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: prepareCommit: flush
[junit4] 2> 76072 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: index before flush
[junit4] 2> 76073 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 startFullFlush
[junit4] 2> 76074 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=2 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76075 T174 C18 oasu.LoggingInfoStream.message [DWFC][qtp1082217009-174]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 76076 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flush postings as segment _0 numDocs=2
[junit4] 2> 76116 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: new segment has 0 deleted docs
[junit4] 2> 76118 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 76119 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4] 2> 76120 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushed codec=Lucene45
[junit4] 2> 76136 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushed: segment=_0 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=3,506.943
[junit4] 2> 76148 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 76149 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: publishFlushedSegment
[junit4] 2> 76150 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: publish sets newSegment delGen=4 seg=_0(5.0):C2
[junit4] 2> 76151 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: now checkpoint "_0(5.0):C2" [1 segments ; isCommit = false]
[junit4] 2> 76152 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: 1 msec to checkpoint
[junit4] 2> 76153 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: apply all deletes during flush
[junit4] 2> 76156 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: applyDeletes: no deletes; skipping
[junit4] 2> 76157 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=4 packetCount=0
[junit4] 2> 76158 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 finishFullFlush success=true
[junit4] 2> 76159 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: findMerges: 1 segments
[junit4] 2> 76161 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: seg=_0(5.0):C2 size=0.000 MB [floored]
[junit4] 2> 76162 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 76163 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: now merge
[junit4] 2> 76164 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: index: _0(5.0):C2
[junit4] 2> 76164 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: no more merges pending; now return
[junit4] 2> 76166 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: startCommit(): start
[junit4] 2> 76167 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: startCommit index=_0(5.0):C2 changeCount=3
[junit4] 2> 76168 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0.si, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4] 2> 76170 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: pendingCommit != null
[junit4] 2> 76171 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: wrote segments file "segments_2"
[junit4] 2> 76172 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: now checkpoint "_0(5.0):C2" [1 segments ; isCommit = true]
[junit4] 2> 76173 T174 C18 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_2,generation=2}
[junit4] 2> 76174 T174 C18 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 76174 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 76175 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: delete "segments_1"
[junit4] 2> 76175 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: 3 msec to checkpoint
[junit4] 2> 76176 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: done
[junit4] 2> 76177 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76177 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 76178 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: flush at getReader
[junit4] 2> 76179 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 startFullFlush
[junit4] 2> 76180 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76182 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: apply all deletes during flush
[junit4] 2> 76183 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: applyDeletes: no deletes; skipping
[junit4] 2> 76184 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=4 packetCount=0
[junit4] 2> 76186 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)
[junit4] 2> 76186 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 finishFullFlush success=true
[junit4] 2> 76187 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: getReader took 9 msec
[junit4] 2> 76188 T174 C18 oass.SolrIndexSearcher.<init> Opening Searcher@50dad531 main
[junit4] 2> 76189 T174 C18 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 76189 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@50dad531 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)}
[junit4] 2> 76194 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 76197 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50dad531 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)}
[junit4] 2> 76198 T174 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 139
[junit4] 2> 76210 T175 C18 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=2 status=0 QTime=1
[junit4] 2> 76215 T170 oas.SolrTestCaseJ4.tearDown ###Ending testUpdateRequestWithParameters
[junit4] 2> 76240 T170 oas.SolrTestCaseJ4.setUp ###Starting testCommitWithinOnAdd
[junit4] 2> 76241 T170 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 76302 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76303 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 76304 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76305 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: flush at getReader
[junit4] 2> 76305 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: qtp1082217009-178 startFullFlush
[junit4] 2> 76306 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76307 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: qtp1082217009-178: flush naked frozen global deletes
[junit4] 2> 76308 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: push deletes 1 deleted queries bytesUsed=32 delGen=7 packetCount=1 totBytesUsed=32
[junit4] 2> 76308 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 76310 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: apply all deletes during flush
[junit4] 2> 76311 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: applyDeletes: infos=[_0(5.0):C2] packetCount=1
[junit4] 2> 76313 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: seg=_0(5.0):C2 segGen=4 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=2 100% deleted
[junit4] 2> 76315 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: applyDeletes took 4 msec
[junit4] 2> 76316 T178 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-178]: now checkpoint "_0(5.0):C2/2" [1 segments ; isCommit = false]
[junit4] 2> 76317 T178 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-178]: 1 msec to checkpoint
[junit4] 2> 76318 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: drop 100% deleted segments: _0(5.0):C2/2
[junit4] 2> 76322 T178 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-178]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 76323 T178 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-178]: 2 msec to checkpoint
[junit4] 2> 76324 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=9223372036854775807 packetCount=1
[junit4] 2> 76324 T178 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-178]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 76325 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 76326 T178 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-178]: qtp1082217009-178 finishFullFlush success=true
[junit4] 2> 76327 T178 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-178]: getReader took 22 msec
[junit4] 2> 76328 T178 C18 oass.SolrIndexSearcher.<init> Opening Searcher@2eed862c realtime
[junit4] 2> 76330 T178 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444887181781893120)} 0 29
[junit4] 2> 76340 T179 C18 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 76341 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: start
[junit4] 2> 76342 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: enter lock
[junit4] 2> 76342 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: now prepare
[junit4] 2> 76343 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: prepareCommit: flush
[junit4] 2> 76343 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: index before flush
[junit4] 2> 76344 T179 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-179]: qtp1082217009-179 startFullFlush
[junit4] 2> 76344 T179 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-179]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76345 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: apply all deletes during flush
[junit4] 2> 76346 T179 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-179]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=9223372036854775807 packetCount=0
[junit4] 2> 76346 T179 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-179]: qtp1082217009-179 finishFullFlush success=true
[junit4] 2> 76347 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: startCommit(): start
[junit4] 2> 76348 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: startCommit index= changeCount=6
[junit4] 2> 76348 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: done all syncs: []
[junit4] 2> 76349 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: pendingCommit != null
[junit4] 2> 76350 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: wrote segments file "segments_3"
[junit4] 2> 76351 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 76351 T179 C18 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_3,generation=3}
[junit4] 2> 76352 T179 C18 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 76353 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 76353 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0.fnm"
[junit4] 2> 76354 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0_Lucene41_0.doc"
[junit4] 2> 76354 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: 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> 76354 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "segments_2"
[junit4] 2> 76355 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0.fdx"
[junit4] 2> 76355 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0.si"
[junit4] 2> 76356 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0_Lucene41_0.tim"
[junit4] 2> 76356 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: 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> 76356 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0.fdt"
[junit4] 2> 76357 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 76357 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: delete "_0_Lucene41_0.tip"
[junit4] 2> 76358 T179 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-179]: 7 msec to checkpoint
[junit4] 2> 76358 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: commit: done
[junit4] 2> 76359 T179 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-179]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76359 T179 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-179]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 76360 T179 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-179]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76360 T179 C18 oass.SolrIndexSearcher.<init> Opening Searcher@6d20c311 main
[junit4] 2> 76361 T179 C18 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 76362 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@6d20c311 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 76362 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 76364 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6d20c311 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 76365 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 76366 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 76366 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 76366 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 76366 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete pending file _0.fdt
[junit4] 2> 76367 T181 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.fdt"
[junit4] 2> 76367 T179 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 27
[junit4] 2> 76377 T174 C18 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1
[junit4] 2> 76400 T175 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[id3 (1444887181871022080)]} 0 14
[junit4] 2> 76407 T177 C18 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1
[junit4] 2> 76901 T184 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 76901 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76901 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: nrtIsCurrent: infoVersion matches: false; DW changes: true; BD changes: false
[junit4] 2> 76902 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: flush at getReader
[junit4] 2> 76902 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: commitScheduler-97-thread-1 startFullFlush
[junit4] 2> 76902 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 76903 T184 oasu.LoggingInfoStream.message [DWFC][commitScheduler-97-thread-1]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 6 ]]
[junit4] 2> 76903 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flush postings as segment _1 numDocs=1
[junit4] 2> 76906 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: new segment has 0 deleted docs
[junit4] 2> 76906 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 76907 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: 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> 76907 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flushed codec=Lucene45
[junit4] 2> 76908 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flushed: segment=_1 ramUsed=0.08 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=696.728
[junit4] 2> 76909 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 76909 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: publishFlushedSegment
[junit4] 2> 76909 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
[junit4] 2> 76910 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: publish sets newSegment delGen=11 seg=_1(5.0):C1
[junit4] 2> 76910 T184 oasu.LoggingInfoStream.message [IFD][commitScheduler-97-thread-1]: now checkpoint "_1(5.0):C1" [1 segments ; isCommit = false]
[junit4] 2> 76910 T184 oasu.LoggingInfoStream.message [IFD][commitScheduler-97-thread-1]: 0 msec to checkpoint
[junit4] 2> 76910 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: apply all deletes during flush
[junit4] 2> 76911 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: applyDeletes: infos=[_1(5.0):C1] packetCount=1
[junit4] 2> 76911 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: applyDeletes took 0 msec
[junit4] 2> 76911 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=12 packetCount=1
[junit4] 2> 76912 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 76914 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)
[junit4] 2> 76914 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: commitScheduler-97-thread-1 finishFullFlush success=true
[junit4] 2> 76914 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: findMerges: 1 segments
[junit4] 2> 76915 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 76915 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 76916 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: now merge
[junit4] 2> 76917 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: index: _1(5.0):C1
[junit4] 2> 76917 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: no more merges pending; now return
[junit4] 2> 76917 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: getReader took 15 msec
[junit4] 2> 76917 T184 oass.SolrIndexSearcher.<init> Opening Searcher@5105e270 main
[junit4] 2> 76918 T184 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 76918 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@5105e270 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 76919 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 76923 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5105e270 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 77415 T174 C18 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id3&wt=javabin&version=2} hits=1 status=0 QTime=1
[junit4] 2> 77424 T175 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[id4 (1444887182957346816)]} 0 2
[junit4] 2> 77925 T184 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 77926 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 77927 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: nrtIsCurrent: infoVersion matches: false; DW changes: true; BD changes: false
[junit4] 2> 77928 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: flush at getReader
[junit4] 2> 77928 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: commitScheduler-97-thread-1 startFullFlush
[junit4] 2> 77929 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 77930 T184 oasu.LoggingInfoStream.message [DWFC][commitScheduler-97-thread-1]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 7 ]]
[junit4] 2> 77931 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flush postings as segment _2 numDocs=1
[junit4] 2> 77938 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: new segment has 0 deleted docs
[junit4] 2> 77938 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 77939 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: 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> 77940 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flushed codec=Lucene45
[junit4] 2> 77941 T184 oasu.LoggingInfoStream.message [DWPT][commitScheduler-97-thread-1]: flushed: segment=_2 ramUsed=0.08 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=696.728
[junit4] 2> 77942 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 77944 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: publishFlushedSegment
[junit4] 2> 77944 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=13 packetCount=1 totBytesUsed=1024
[junit4] 2> 77945 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: publish sets newSegment delGen=14 seg=_2(5.0):C1
[junit4] 2> 77945 T184 oasu.LoggingInfoStream.message [IFD][commitScheduler-97-thread-1]: now checkpoint "_1(5.0):C1 _2(5.0):C1" [2 segments ; isCommit = false]
[junit4] 2> 77946 T184 oasu.LoggingInfoStream.message [IFD][commitScheduler-97-thread-1]: 0 msec to checkpoint
[junit4] 2> 77947 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: apply all deletes during flush
[junit4] 2> 77948 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: applyDeletes: infos=[_1(5.0):C1, _2(5.0):C1] packetCount=1
[junit4] 2> 77948 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: seg=_1(5.0):C1 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 77949 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: applyDeletes took 1 msec
[junit4] 2> 77950 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=15 packetCount=1
[junit4] 2> 77950 T184 oasu.LoggingInfoStream.message [BD][commitScheduler-97-thread-1]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 77954 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt _1(5.0):C1 _2(5.0):C1)
[junit4] 2> 77955 T184 oasu.LoggingInfoStream.message [DW][commitScheduler-97-thread-1]: commitScheduler-97-thread-1 finishFullFlush success=true
[junit4] 2> 77955 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: findMerges: 2 segments
[junit4] 2> 77957 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 77958 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: seg=_2(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 77959 T184 oasu.LoggingInfoStream.message [TMP][commitScheduler-97-thread-1]: allowedSegmentCount=1 vs count=2 (eligible count=2) tooBigCount=0
[junit4] 2> 77959 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: now merge
[junit4] 2> 77960 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: index: _1(5.0):C1 _2(5.0):C1
[junit4] 2> 77961 T184 oasu.LoggingInfoStream.message [CMS][commitScheduler-97-thread-1]: no more merges pending; now return
[junit4] 2> 77961 T184 oasu.LoggingInfoStream.message [IW][commitScheduler-97-thread-1]: getReader took 33 msec
[junit4] 2> 77962 T184 oass.SolrIndexSearcher.<init> Opening Searcher@7e788896 main
[junit4] 2> 77964 T184 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 77964 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@7e788896 main{StandardDirectoryReader(segments_3:9:nrt _1(5.0):C1 _2(5.0):C1)}
[junit4] 2> 77965 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 77971 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e788896 main{StandardDirectoryReader(segments_3:9:nrt _1(5.0):C1 _2(5.0):C1)}
[junit4] 2> 78437 T178 C18 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:id4&wt=javabin&version=2} hits=1 status=0 QTime=3
[junit4] 2> 78442 T170 oas.SolrTestCaseJ4.tearDown ###Ending testCommitWithinOnAdd
[junit4] 2> 78476 T170 oas.SolrTestCaseJ4.setUp ###Starting testSetNullUpdates
[junit4] 2> 78487 T179 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdates (1444887184069885952)]} 0 4
[junit4] 2> 78496 T174 C18 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 78497 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: start
[junit4] 2> 78498 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: enter lock
[junit4] 2> 78499 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: now prepare
[junit4] 2> 78500 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: prepareCommit: flush
[junit4] 2> 78502 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: index before flush _1(5.0):C1 _2(5.0):C1
[junit4] 2> 78503 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 startFullFlush
[junit4] 2> 78504 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 78505 T174 C18 oasu.LoggingInfoStream.message [DWFC][qtp1082217009-174]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_3, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 8 ]]
[junit4] 2> 78506 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flush postings as segment _3 numDocs=1
[junit4] 2> 78511 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: new segment has 0 deleted docs
[junit4] 2> 78512 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 78513 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushedFiles=[_3.fdx, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.fnm, _3_Lucene41_0.tim, _3.fdt]
[junit4] 2> 78514 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushed codec=Lucene45
[junit4] 2> 78516 T174 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-174]: flushed: segment=_3 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,154.819
[junit4] 2> 78517 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 78519 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: publishFlushedSegment
[junit4] 2> 78520 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=16 packetCount=1 totBytesUsed=1024
[junit4] 2> 78520 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: publish sets newSegment delGen=17 seg=_3(5.0):C1
[junit4] 2> 78521 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _3(5.0):C1" [3 segments ; isCommit = false]
[junit4] 2> 78523 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: 1 msec to checkpoint
[junit4] 2> 78526 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: apply all deletes during flush
[junit4] 2> 78527 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: applyDeletes: infos=[_1(5.0):C1, _2(5.0):C1, _3(5.0):C1] packetCount=1
[junit4] 2> 78528 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: seg=_2(5.0):C1 segGen=15 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 78529 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: seg=_1(5.0):C1 segGen=15 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 78530 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: applyDeletes took 3 msec
[junit4] 2> 78531 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=18 packetCount=1
[junit4] 2> 78532 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 78533 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 finishFullFlush success=true
[junit4] 2> 78534 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: findMerges: 3 segments
[junit4] 2> 78536 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78537 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: seg=_2(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78538 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: seg=_3(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78539 T174 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-174]: allowedSegmentCount=1 vs count=3 (eligible count=3) tooBigCount=0
[junit4] 2> 78540 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: now merge
[junit4] 2> 78542 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: index: _1(5.0):C1 _2(5.0):C1 _3(5.0):C1
[junit4] 2> 78542 T174 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-174]: no more merges pending; now return
[junit4] 2> 78543 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: startCommit(): start
[junit4] 2> 78544 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: startCommit index=_1(5.0):C1 _2(5.0):C1 _3(5.0):C1 changeCount=13
[junit4] 2> 78546 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: done all syncs: [_2.si, _2_Lucene41_0.pos, _1_Lucene41_0.doc, _2_Lucene41_0.tim, _3.fdt, _3.fnm, _2_Lucene41_0.tip, _1.fnm, _3_Lucene41_0.tip, _3_Lucene41_0.tim, _1.nvm, _1_Lucene41_0.tim, _1.nvd, _2.fdt, _1_Lucene41_0.tip, _2_Lucene41_0.doc, _2.fdx, _2.fnm, _3.fdx, _1.fdx, _1_Lucene41_0.pos, _2.nvm, _3_Lucene41_0.doc, _1.fdt, _1.si, _2.nvd, _3.si]
[junit4] 2> 78547 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: pendingCommit != null
[junit4] 2> 78548 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: wrote segments file "segments_4"
[junit4] 2> 78549 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _3(5.0):C1" [3 segments ; isCommit = true]
[junit4] 2> 78550 T174 C18 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_4,generation=4}
[junit4] 2> 78550 T174 C18 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 78551 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 78552 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: delete "segments_3"
[junit4] 2> 78553 T174 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-174]: 4 msec to checkpoint
[junit4] 2> 78554 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: commit: done
[junit4] 2> 78555 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 78556 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 78557 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: flush at getReader
[junit4] 2> 78557 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 startFullFlush
[junit4] 2> 78558 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 78559 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: apply all deletes during flush
[junit4] 2> 78560 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: applyDeletes: no deletes; skipping
[junit4] 2> 78561 T174 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-174]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=18 packetCount=0
[junit4] 2> 78564 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: return reader version=11 reader=StandardDirectoryReader(segments_4:11:nrt _1(5.0):C1 _2(5.0):C1 _3(5.0):C1)
[junit4] 2> 78565 T174 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-174]: qtp1082217009-174 finishFullFlush success=true
[junit4] 2> 78566 T174 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-174]: getReader took 9 msec
[junit4] 2> 78567 T174 C18 oass.SolrIndexSearcher.<init> Opening Searcher@213e7e70 main
[junit4] 2> 78568 T174 C18 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 78570 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@213e7e70 main{StandardDirectoryReader(segments_4:11:nrt _1(5.0):C1 _2(5.0):C1 _3(5.0):C1)}
[junit4] 2> 78570 T181 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 78577 T181 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@213e7e70 main{StandardDirectoryReader(segments_4:11:nrt _1(5.0):C1 _2(5.0):C1 _3(5.0):C1)}
[junit4] 2> 78579 T174 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 83
[junit4] 2> 78605 T175 C18 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdates (1444887184193617920)]} 0 14
[junit4] 2> 78615 T176 C18 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 78616 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: start
[junit4] 2> 78619 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: enter lock
[junit4] 2> 78620 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: now prepare
[junit4] 2> 78620 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: prepareCommit: flush
[junit4] 2> 78626 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: index before flush _1(5.0):C1 _2(5.0):C1 _3(5.0):C1
[junit4] 2> 78626 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: qtp1082217009-176 startFullFlush
[junit4] 2> 78627 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 78628 T176 C18 oasu.LoggingInfoStream.message [DWFC][qtp1082217009-176]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_4, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 10 ]]
[junit4] 2> 78628 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: flush postings as segment _4 numDocs=1
[junit4] 2> 78631 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: new segment has 0 deleted docs
[junit4] 2> 78631 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 78632 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: flushedFiles=[_4.fdx, _4_Lucene41_0.doc, _4.fnm, _4.fdt, _4_Lucene41_0.tip, _4_Lucene41_0.tim]
[junit4] 2> 78632 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: flushed codec=Lucene45
[junit4] 2> 78633 T176 C18 oasu.LoggingInfoStream.message [DWPT][qtp1082217009-176]: flushed: segment=_4 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,394.383
[junit4] 2> 78634 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 78635 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: publishFlushedSegment
[junit4] 2> 78635 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=20 packetCount=1 totBytesUsed=1024
[junit4] 2> 78636 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: publish sets newSegment delGen=21 seg=_4(5.0):C1
[junit4] 2> 78636 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _3(5.0):C1 _4(5.0):C1" [4 segments ; isCommit = false]
[junit4] 2> 78637 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: 0 msec to checkpoint
[junit4] 2> 78637 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: apply all deletes during flush
[junit4] 2> 78638 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: applyDeletes: infos=[_1(5.0):C1, _2(5.0):C1, _3(5.0):C1, _4(5.0):C1] packetCount=1
[junit4] 2> 78639 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: seg=_3(5.0):C1 segGen=18 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=1 100% deleted
[junit4] 2> 78640 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: seg=_2(5.0):C1 segGen=18 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 78640 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: seg=_1(5.0):C1 segGen=18 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 78641 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: applyDeletes took 3 msec
[junit4] 2> 78641 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _3(5.0):C1/1 _4(5.0):C1" [4 segments ; isCommit = false]
[junit4] 2> 78642 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: 0 msec to checkpoint
[junit4] 2> 78643 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: drop 100% deleted segments: _3(5.0):C1/1
[junit4] 2> 78643 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _4(5.0):C1" [3 segments ; isCommit = false]
[junit4] 2> 78644 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: 0 msec to checkpoint
[junit4] 2> 78645 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=22 packetCount=1
[junit4] 2> 78646 T176 C18 oasu.LoggingInfoStream.message [BD][qtp1082217009-176]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 78646 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: qtp1082217009-176 finishFullFlush success=true
[junit4] 2> 78647 T176 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-176]: findMerges: 3 segments
[junit4] 2> 78648 T176 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-176]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78648 T176 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-176]: seg=_2(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78649 T176 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-176]: seg=_4(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 78650 T176 C18 oasu.LoggingInfoStream.message [TMP][qtp1082217009-176]: allowedSegmentCount=1 vs count=3 (eligible count=3) tooBigCount=0
[junit4] 2> 78650 T176 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-176]: now merge
[junit4] 2> 78651 T176 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-176]: index: _1(5.0):C1 _2(5.0):C1 _4(5.0):C1
[junit4] 2> 78651 T176 C18 oasu.LoggingInfoStream.message [CMS][qtp1082217009-176]: no more merges pending; now return
[junit4] 2> 78652 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: startCommit(): start
[junit4] 2> 78652 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: startCommit index=_1(5.0):C1 _2(5.0):C1 _4(5.0):C1 changeCount=18
[junit4] 2> 78653 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: done all syncs: [_2.si, _2_Lucene41_0.pos, _1_Lucene41_0.doc, _2_Lucene41_0.tim, _4_Lucene41_0.doc, _4.fnm, _2_Lucene41_0.tip, _1.fnm, _4.fdx, _1.nvm, _1_Lucene41_0.tim, _1.nvd, _2.fdt, _1_Lucene41_0.tip, _4.si, _2_Lucene41_0.doc, _4.fdt, _4_Lucene41_0.tip, _2.fdx, _4_Lucene41_0.tim, _2.fnm, _1.fdx, _1_Lucene41_0.pos, _2.nvm, _1.fdt, _1.si, _2.nvd]
[junit4] 2> 78654 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: pendingCommit != null
[junit4] 2> 78655 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: wrote segments file "segments_5"
[junit4] 2> 78655 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: now checkpoint "_1(5.0):C1 _2(5.0):C1 _4(5.0):C1" [3 segments ; isCommit = true]
[junit4] 2> 78656 T176 C18 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@676d9b56 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e712c5),segFN=segments_5,generation=5}
[junit4] 2> 78657 T176 C18 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 78657 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 78657 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3.fdt"
[junit4] 2> 78658 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: unable to remove file "_3.fdt": java.io.IOException: MockDirectoryWrapper: file "_3.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 78659 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3.fnm"
[junit4] 2> 78659 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3_Lucene41_0.tip"
[junit4] 2> 78660 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3_Lucene41_0.tim"
[junit4] 2> 78660 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: unable to remove file "_3_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_3_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 78661 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3.fdx"
[junit4] 2> 78662 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3_Lucene41_0.doc"
[junit4] 2> 78662 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: unable to remove file "_3_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_3_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 78663 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "_3.si"
[junit4] 2> 78663 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: delete "segments_4"
[junit4] 2> 78664 T176 C18 oasu.LoggingInfoStream.message [IFD][qtp1082217009-176]: 8 msec to checkpoint
[junit4] 2> 78664 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: commit: done
[junit4] 2> 78665 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 78665 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 78666 T176 C18 oasu.LoggingInfoStream.message [IW][qtp1082217009-176]: flush at getReader
[junit4] 2> 78666 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: qtp1082217009-176 startFullFlush
[junit4] 2> 78667 T176 C18 oasu.LoggingInfoStream.message [DW][qtp1082217009-176]: anyChang
[...truncated too long message...]
=javabin&fq={!tag%3Dmytag}-(features:bbb+AND+cat:a+AND+inStock:true)&facet.pivot={!ex%3Dmytag+key%3Dmykey}features,cat&version=2&rows=0} hits=11 status=0 QTime=3
[junit4] 2> 290376 T170 oas.SolrTestCaseJ4.tearDown ###Ending testPivotFacets
[junit4] 2> 290411 T170 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1459784621
[junit4] 2> 290414 T170 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@ce9c2fd
[junit4] 2> 290547 T170 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=60,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=152,cumulative_deletesById=5,cumulative_deletesByQuery=28,cumulative_errors=1}
[junit4] 2> 290552 T170 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 290553 T170 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 290554 T170 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 290558 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: now flush at close waitForMerges=true
[junit4] 2> 290559 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 290561 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: index before flush _16(5.0):C12
[junit4] 2> 290563 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker startFullFlush
[junit4] 2> 290564 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 290565 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker finishFullFlush success=true
[junit4] 2> 290567 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: apply all deletes during flush
[junit4] 2> 290568 T170 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 290569 T170 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=242 packetCount=0
[junit4] 2> 290570 T170 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: now merge
[junit4] 2> 290571 T170 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: index: _16(5.0):C12
[junit4] 2> 290573 T170 C22 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: no more merges pending; now return
[junit4] 2> 290574 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: waitForMerges
[junit4] 2> 290575 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: waitForMerges done
[junit4] 2> 290576 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: now call final commit()
[junit4] 2> 290577 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: commit: start
[junit4] 2> 290578 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: commit: enter lock
[junit4] 2> 290579 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: commit: now prepare
[junit4] 2> 290580 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: prepareCommit: flush
[junit4] 2> 290582 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: index before flush _16(5.0):C12
[junit4] 2> 290582 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker startFullFlush
[junit4] 2> 290584 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 290585 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: apply all deletes during flush
[junit4] 2> 290586 T170 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 290588 T170 C22 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@3cb8899a minGen=242 packetCount=0
[junit4] 2> 290589 T170 C22 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker finishFullFlush success=true
[junit4] 2> 290590 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: startCommit(): start
[junit4] 2> 290591 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: skip startCommit(): no changes pending
[junit4] 2> 290593 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 290594 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: commit: done
[junit4] 2> 290595 T170 C22 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[DF8D4B9857AD7D31]-worker]: at close: _16(5.0):C12
[junit4] 2> 290601 T170 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 290602 T170 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 290604 T170 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604;done=false>>]
[junit4] 2> 290605 T170 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604
[junit4] 2> 290606 T170 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index;done=false>>]
[junit4] 2> 290607 T170 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleJettyTest-1377951792604/index
[junit4] 2> 290609 T170 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 290665 T170 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=sr, timezone=NZ
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=53944008,total=97517568
[junit4] 2> NOTE: All tests run in this JVM: [TestXMLEscaping, ContentStreamTest, TestEmbeddedSolrServer, SolrQueryTest, ClientUtilsTest, TestHash, SolrDocumentTest, SolrParamTest, TestBatchUpdate, MultiCoreExampleJettyTest, LargeVolumeJettyTest, TestDocumentObjectBinder, JettyWebappTest, TestSpellCheckResponse, TestNamedListCodec, SolrExceptionTest, LargeVolumeBinaryJettyTest, SolrExampleJettyTest]
[junit4] Completed in 217.36s, 27 tests, 1 error <<< FAILURES!
[...truncated 93 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:396: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:376: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:202: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:455: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1230: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:873: There were test failures: 46 suites, 272 tests, 1 error
Total time: 109 minutes 6 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure