You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/12/09 18:52:43 UTC
[JENKINS] Lucene-Solr-Tests-5.x-Java7 - Build # 2302 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-5.x-Java7/2302/
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testArbitraryJsonIndexing
Error Message:
Stack Trace:
java.lang.NullPointerException
at __randomizedtesting.SeedInfo.seed([9899A23A4DB4B301:6C86B8918CDBA669]:0)
at org.noggit.JSONParser.<init>(JSONParser.java:131)
at org.noggit.ObjectBuilder.fromJSON(ObjectBuilder.java:32)
at org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testArbitraryJsonIndexing(SolrExampleJettyTest.java:91)
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:1618)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
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.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:65)
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:365)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:54)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
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:365)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 10777 lines...]
[junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest
[junit4] 2> Creating dataDir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/init-core-data-001
[junit4] 2> 88503 T112 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 88504 T112 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 88505 T112 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 88508 T112 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:56829
[junit4] 2> 88509 T112 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 88509 T112 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 88509 T112 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001
[junit4] 2> 88510 T112 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/'
[junit4] 2> 88536 T112 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/solr.xml
[junit4] 2> 88578 T112 oasc.CorePropertiesLocator.<init> Config-defined core root directory: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001
[junit4] 2> 88578 T112 oasc.CoreContainer.<init> New CoreContainer 262157179
[junit4] 2> 88578 T112 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/]
[junit4] 2> 88579 T112 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 88579 T112 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: null
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting maxConnections to: 10000
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 88580 T112 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 88581 T112 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 88581 T112 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 88581 T112 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 88582 T112 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 88582 T112 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 88582 T112 oasc.CoreContainer.load Host Name:
[junit4] 2> 88585 T112 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001
[junit4] 2> 88586 T112 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/
[junit4] 2> 88587 T112 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 88587 T122 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/'
[junit4] 2> 88615 T122 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 88616 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../contrib/extraction/lib (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../contrib/extraction/lib).
[junit4] 2> 88616 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../dist).
[junit4] 2> 88617 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../contrib/clustering/lib/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../contrib/clustering/lib).
[junit4] 2> 88617 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../dist).
[junit4] 2> 88618 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../contrib/langid/lib/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../contrib/langid/lib).
[junit4] 2> 88618 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../dist).
[junit4] 2> 88619 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../contrib/velocity/lib (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../contrib/velocity/lib).
[junit4] 2> 88620 T122 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/../../../dist).
[junit4] 2> 88656 T122 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 88659 T122 oasc.SolrConfig.<init> Using Lucene MatchVersion: 5.0.0
[junit4] 2> 88715 T122 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 88716 T122 oass.IndexSchema.readSchema Reading Solr Schema from /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf/schema.xml
[junit4] 2> 88752 T122 oass.IndexSchema.readSchema [collection1] Schema name=example
[junit4] 2> 89215 T122 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 89218 T122 oasr.RestManager$Registry.registerManagedResource Registered ManagedResource impl org.apache.solr.rest.schema.analysis.ManagedWordSetResource for path /schema/analysis/stopwords/english
[junit4] 2> 89218 T122 oasr.RestManager$Registry.registerManagedResource Registered ManagedResource impl org.apache.solr.rest.schema.analysis.ManagedSynonymFilterFactory$SynonymManager for path /schema/analysis/synonyms/english
[junit4] 2> 89247 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 89254 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 89301 T122 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from instancedir /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/
[junit4] 2> 89302 T122 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 89302 T122 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/, dataDir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/
[junit4] 2> 89302 T122 oasc.JmxMonitoredMap.<init> No JMX servers found, not exposing Solr information with JMX.
[junit4] 2> 89302 T122 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 89303 T122 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 89303 T122 oasc.CachingDirectoryFactory.get return new directory for /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002
[junit4] 2> 89304 T122 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index/
[junit4] 2> 89304 T122 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index' doesn't exist. Creating new index...
[junit4] 2> 89304 T122 oasc.CachingDirectoryFactory.get return new directory for /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index
[junit4] 2> 89305 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: init: current segments file is "segments"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@4a3b7fdd
[junit4] 2> 89306 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 89306 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: 0 msec to checkpoint
[junit4] 2> 89306 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: init: create=true
[junit4] 2> 89306 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]:
[junit4] 2> dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9)
[junit4] 2> index=
[junit4] 2> version=5.0.0
[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=Lucene50
[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.DocumentsWriterPerThreadPool@197d1eb1
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2> commitOnClose=true
[junit4] 2> writer=org.apache.lucene.util.SetOnce@656a0389
[junit4] 2>
[junit4] 2> 89307 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: now flush at close
[junit4] 2> 89307 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 89307 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: index before flush
[junit4] 2> 89307 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: startFullFlush
[junit4] 2> 89308 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: coreLoadExecutor-75-thread-1 finishFullFlush success=true
[junit4] 2> 89308 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: apply all deletes during flush
[junit4] 2> 89308 T122 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-75-thread-1]: prune sis=segments: minGen=9223372036854775807 packetCount=0
[junit4] 2> 89308 T122 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-75-thread-1]: now merge
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-75-thread-1]: index:
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-75-thread-1]: no more merges pending; now return
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: waitForMerges
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: waitForMerges done
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: start
[junit4] 2> 89309 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: enter lock
[junit4] 2> 89310 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: now prepare
[junit4] 2> 89310 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: prepareCommit: flush
[junit4] 2> 89310 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: index before flush
[junit4] 2> 89310 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: startFullFlush
[junit4] 2> 89310 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: apply all deletes during flush
[junit4] 2> 89311 T122 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-75-thread-1]: prune sis=segments: minGen=9223372036854775807 packetCount=0
[junit4] 2> 89311 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: coreLoadExecutor-75-thread-1 finishFullFlush success=true
[junit4] 2> 89311 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: startCommit(): start
[junit4] 2> 89311 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: startCommit index= changeCount=1
[junit4] 2> 89311 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: done all syncs: []
[junit4] 2> 89312 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: pendingCommit != null
[junit4] 2> 89312 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 89312 T122 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_1,generation=1}
[junit4] 2> 89312 T122 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 89313 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: 0 msec to checkpoint
[junit4] 2> 89313 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 89313 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: took 3.2 msec
[junit4] 2> 89313 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: commit: done
[junit4] 2> 89313 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: rollback
[junit4] 2> 89314 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: all running merges have aborted
[junit4] 2> 89314 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: rollback: done finish merges
[junit4] 2> 89314 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: abort
[junit4] 2> 89314 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: done abort success=true
[junit4] 2> 89314 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: rollback: infos=
[junit4] 2> 89315 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 89315 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: 0 msec to checkpoint
[junit4] 2> 89315 T122 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 89315 T122 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 89315 T122 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 89316 T122 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 89316 T122 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 89317 T122 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 89318 T122 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 89318 T122 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 89318 T122 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 89319 T122 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 89319 T122 oasc.RequestHandlers.initHandlersFromConfig created /config: org.apache.solr.handler.SolrConfigHandler
[junit4] 2> 89319 T122 oasc.RequestHandlers.initHandlersFromConfig created /schema: org.apache.solr.handler.SchemaHandler
[junit4] 2> 89320 T122 oasc.RequestHandlers.initHandlersFromConfig created /replication: org.apache.solr.handler.ReplicationHandler
[junit4] 2> 89320 T122 oasc.RequestHandlers.initHandlersFromConfig created /get: org.apache.solr.handler.RealTimeGetHandler
[junit4] 2> 89320 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/luke: org.apache.solr.handler.admin.LukeRequestHandler
[junit4] 2> 89321 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/system: org.apache.solr.handler.admin.SystemInfoHandler
[junit4] 2> 89322 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/mbeans: org.apache.solr.handler.admin.SolrInfoMBeanHandler
[junit4] 2> 89322 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/plugins: org.apache.solr.handler.admin.PluginInfoHandler
[junit4] 2> 89322 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/threads: org.apache.solr.handler.admin.ThreadDumpHandler
[junit4] 2> 89323 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/properties: org.apache.solr.handler.admin.PropertiesRequestHandler
[junit4] 2> 89323 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/logging: org.apache.solr.handler.admin.LoggingHandler
[junit4] 2> 89323 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: org.apache.solr.handler.admin.ShowFileRequestHandler
[junit4] 2> 89324 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: org.apache.solr.handler.PingRequestHandler
[junit4] 2> 89324 T122 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 89324 T122 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 89324 T122 oasc.RequestHandlers.initHandlersFromConfig created /export: solr.SearchHandler
[junit4] 2> 89325 T122 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 89325 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 89325 T122 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 89325 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 89325 T122 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 89326 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 89326 T122 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 89326 T122 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 89326 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 89326 T122 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 89327 T122 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 89343 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 89345 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 89347 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 89348 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 89354 T122 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 89354 T122 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 89355 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@4a3b7fdd
[junit4] 2> 89355 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: init: load commit "segments_1"
[junit4] 2> 89356 T122 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_1,generation=1}
[junit4] 2> 89356 T122 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 89356 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 89356 T122 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-75-thread-1]: 0 msec to checkpoint
[junit4] 2> 89356 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: init: create=false
[junit4] 2> 89357 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]:
[junit4] 2> dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9)
[junit4] 2> index=
[junit4] 2> version=5.0.0
[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=Lucene50
[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.DocumentsWriterPerThreadPool@174f78fa
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2> commitOnClose=true
[junit4] 2> writer=org.apache.lucene.util.SetOnce@628f710a
[junit4] 2>
[junit4] 2> 89357 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: flush at getReader
[junit4] 2> 89357 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: startFullFlush
[junit4] 2> 89358 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: apply all deletes during flush
[junit4] 2> 89358 T122 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-75-thread-1]: prune sis=segments_1: minGen=9223372036854775807 packetCount=0
[junit4] 2> 89358 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 89358 T122 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-75-thread-1]: coreLoadExecutor-75-thread-1 finishFullFlush success=true
[junit4] 2> 89358 T122 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-75-thread-1]: getReader took 1 msec
[junit4] 2> 89359 T122 oass.SolrIndexSearcher.<init> Opening Searcher@73f891be[collection1] main
[junit4] 2> 89360 T122 oasr.ManagedResourceStorage$FileStorageIO.configure File-based storage initialized to use dir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89360 T122 oasr.RestManager.init Initializing RestManager with initArgs: {storageDir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf}
[junit4] 2> 89360 T122 oasr.ManagedResourceStorage.load Reading _rest_managed.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89361 T122 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89361 T122 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
[junit4] 2> 89361 T122 oasr.RestManager.init Initializing 2 registered ManagedResources
[junit4] 2> 89362 T122 oasr.ManagedResourceStorage.load Reading _schema_analysis_stopwords_english.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89362 T122 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _schema_analysis_stopwords_english.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89363 T122 oasr.ManagedResource.reloadFromStorage Loaded initArgs {ignoreCase=true} for /schema/analysis/stopwords/english
[junit4] 2> 89363 T122 oasrsa.ManagedWordSetResource.onManagedDataLoadedFromStorage Loaded 35 words for /schema/analysis/stopwords/english
[junit4] 2> 89363 T122 oasr.ManagedResource.notifyObserversDuringInit Notified 1 observers of /schema/analysis/stopwords/english
[junit4] 2> 89363 T122 oasr.ManagedResourceStorage.load Reading _schema_analysis_synonyms_english.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89364 T122 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _schema_analysis_synonyms_english.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf
[junit4] 2> 89364 T122 oasr.ManagedResource.reloadFromStorage Loaded initArgs {ignoreCase=true,format=solr} for /schema/analysis/synonyms/english
[junit4] 2> 89365 T122 oasrsa.ManagedSynonymFilterFactory$SynonymManager.onManagedDataLoadedFromStorage Loaded 3 synonym mappings for /schema/analysis/synonyms/english
[junit4] 2> 89365 T122 oasr.ManagedResource.notifyObserversDuringInit Notified 1 observers of /schema/analysis/synonyms/english
[junit4] 2> 89366 T122 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 89366 T122 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> 89366 T122 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 89368 T122 oashc.QueryElevationComponent.inform Loading QueryElevation from: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-001/collection1/conf/elevate.xml
[junit4] 2> 89379 T122 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 89379 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@73f891be[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 89379 T122 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 89380 T112 oass.SolrDispatchFilter.init user.dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2
[junit4] 2> 89380 T112 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> ASYNC NEW_CORE C15 name=collection1 org.apache.solr.core.SolrCore@4267f188
[junit4] 2> 89380 T123 C15 oasc.SolrCore.execute [collection1] webapp=null path=null params={distrib=false&event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml} hits=0 status=0 QTime=0
[junit4] 2> 89381 T112 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#56829
[junit4] 2> 89381 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89381 T123 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 89381 T123 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 89381 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@73f891be[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 89387 T112 oas.SolrTestCaseJ4.setUp ###Starting testStreamingRequest
[junit4] 2> 89391 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89392 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89392 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 89392 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: flush at getReader
[junit4] 2> 89392 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89392 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89393 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115: flush naked frozen global deletes
[junit4] 2> 89393 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: push deletes 1 deleted queries bytesUsed=64 delGen=2 packetCount=1 totBytesUsed=64
[junit4] 2> 89393 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: flush: push buffered updates: 1 deleted queries bytesUsed=64
[junit4] 2> 89394 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89394 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: minGen=9223372036854775807 packetCount=1
[junit4] 2> 89394 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89394 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 89394 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89395 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: getReader took 3 msec
[junit4] 2> 89395 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1487034325428862976)} 0 5
[junit4] 2> 89398 T115 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89398 T115 C15 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 89399 T115 C15 oasc.SolrCore.openNewSearcher SolrIndexSearcher has not changed - not re-opening: org.apache.solr.search.SolrIndexSearcher
[junit4] 2> 89399 T115 C15 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89399 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&softCommit=false&wt=javabin&commit=true&waitSearcher=true} {commit=} 0 1
[junit4] 2> 89402 T115 C15 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={version=2&wt=javabin&q=*:*} hits=0 status=0 QTime=0
[junit4] 2> 89408 T115 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89408 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: start
[junit4] 2> 89408 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: enter lock
[junit4] 2> 89408 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: now prepare
[junit4] 2> 89408 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: prepareCommit: flush
[junit4] 2> 89409 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: index before flush
[junit4] 2> 89409 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89409 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89409 T115 C15 oasu.LoggingInfoStream.message [DWFC][qtp557502298-115]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=1485, segment=_0, aborted=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 89409 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flush postings as segment _0 numDocs=10
[junit4] 2> 89411 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has 0 deleted docs
[junit4] 2> 89411 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 89411 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushedFiles=[_0_Lucene50_0.pos, _0.fnm, _0.nvd, _0.nvm, _0.fdx, _0.fdt, _0_Lucene50_0.tim, _0_Lucene50_0.tip, _0_Lucene50_0.doc]
[junit4] 2> 89411 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed codec=Lucene50
[junit4] 2> 89412 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed: segment=_0 ramUsed=0.097 MB newFlushedSize(includes docstores)=0.002 MB docs/MB=6,186.289
[junit4] 2> 89412 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: publishFlushedSegment seg-private updates=null
[junit4] 2> 89412 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publishFlushedSegment
[junit4] 2> 89413 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: push deletes 10 deleted terms (unique count=10) bytesUsed=1056 delGen=4 packetCount=1 totBytesUsed=1056
[junit4] 2> 89413 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publish sets newSegment delGen=5 seg=_0(5.0.0):C10
[junit4] 2> 89413 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10" [1 segments ; isCommit = false]
[junit4] 2> 89413 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89413 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89414 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: infos=[_0(5.0.0):C10] packetCount=1
[junit4] 2> 89414 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes took 0 msec
[junit4] 2> 89414 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 minGen=6 packetCount=1
[junit4] 2> 89414 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89415 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89415 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: findMerges: 1 segments
[junit4] 2> 89415 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: seg=_0(5.0.0):C10 size=0.002 MB [floored]
[junit4] 2> 89415 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 89415 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: now merge
[junit4] 2> 89416 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: index: _0(5.0.0):C10
[junit4] 2> 89416 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: no more merges pending; now return
[junit4] 2> 89416 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit(): start
[junit4] 2> 89416 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit index=_0(5.0.0):C10 changeCount=3
[junit4] 2> 89417 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: done all syncs: [_0.fnm, _0_Lucene50_0.pos, _0.nvm, _0.nvd, _0.fdx, _0.fdt, _0_Lucene50_0.tim, _0_Lucene50_0.tip, _0.si, _0_Lucene50_0.doc]
[junit4] 2> 89417 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: pendingCommit != null
[junit4] 2> 89417 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10" [1 segments ; isCommit = true]
[junit4] 2> 89417 T115 C15 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_2,generation=2}
[junit4] 2> 89418 T115 C15 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 89418 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 89418 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: delete "segments_1"
[junit4] 2> 89418 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 1 msec to checkpoint
[junit4] 2> 89419 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: wrote segments file "segments_2"
[junit4] 2> 89419 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: took 10.4 msec
[junit4] 2> 89419 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: done
[junit4] 2> 89419 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 89419 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: flush at getReader
[junit4] 2> 89420 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89420 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89420 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: no deletes; skipping
[junit4] 2> 89420 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 minGen=6 packetCount=0
[junit4] 2> 89421 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: return reader version=3 reader=StandardDirectoryReader(segments_1:3:nrt _0(5.0.0):C10)
[junit4] 2> 89422 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89422 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: getReader took 3 msec
[junit4] 2> 89422 T115 C15 oass.SolrIndexSearcher.<init> Opening Searcher@6c11732[collection1] main
[junit4] 2> 89423 T115 C15 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89423 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@6c11732[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10)))}
[junit4] 2> 89423 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89423 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6c11732[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10)))}
[junit4] 2> 89424 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&softCommit=false&wt=javabin&commit=true&waitSearcher=true} {add=[0 (1487034325444591616), 1 (1487034325446688768), 2 (1487034325446688769), 3 (1487034325446688770), 4 (1487034325446688771), 5 (1487034325446688772), 6 (1487034325446688773), 7 (1487034325446688774), 8 (1487034325446688775), 9 (1487034325447737344)],commit=} 0 18
[junit4] 2> 89427 T115 C15 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={version=2&wt=javabin&fl=id,score,_docid_&q=*:*} hits=10 status=0 QTime=0
[junit4] 2> 89431 T115 C15 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={version=2&wt=javabin&fl=id,score,_docid_&q=*:*} hits=10 status=0 QTime=0
[junit4] 2> 89432 T112 oas.SolrTestCaseJ4.tearDown ###Ending testStreamingRequest
[junit4] 2> 89439 T112 oas.SolrTestCaseJ4.setUp ###Starting testSetNullUpdates
[junit4] 2> 89443 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&wt=javabin} {add=[testSetNullUpdates (1487034325483388928)]} 0 1
[junit4] 2> 89446 T115 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89446 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: start
[junit4] 2> 89446 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: enter lock
[junit4] 2> 89446 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: now prepare
[junit4] 2> 89447 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: prepareCommit: flush
[junit4] 2> 89447 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: index before flush _0(5.0.0):C10
[junit4] 2> 89447 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89447 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89447 T115 C15 oasu.LoggingInfoStream.message [DWFC][qtp557502298-115]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborted=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 4 ]]
[junit4] 2> 89448 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flush postings as segment _1 numDocs=1
[junit4] 2> 89449 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has 0 deleted docs
[junit4] 2> 89449 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 89449 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushedFiles=[_1_Lucene50_0.tip, _1_Lucene50_0.doc, _1_Lucene50_0.tim, _1.fnm, _1.fdt, _1.fdx]
[junit4] 2> 89449 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed codec=Lucene50
[junit4] 2> 89450 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed: segment=_1 ramUsed=0.095 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=799.22
[junit4] 2> 89450 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: publishFlushedSegment seg-private updates=null
[junit4] 2> 89450 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publishFlushedSegment
[junit4] 2> 89451 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: push deletes 1 deleted terms (unique count=1) bytesUsed=1056 delGen=8 packetCount=1 totBytesUsed=1056
[junit4] 2> 89451 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publish sets newSegment delGen=9 seg=_1(5.0.0):C1
[junit4] 2> 89451 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _1(5.0.0):C1" [2 segments ; isCommit = false]
[junit4] 2> 89451 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89451 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89452 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: infos=[_0(5.0.0):C10, _1(5.0.0):C1] packetCount=1
[junit4] 2> 89452 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: seg=_0(5.0.0):C10 segGen=6 coalesced deletes=[CoalescedUpdates(termSets=1,queries=0,numericDVUpdates=0,binaryDVUpdates=0)] newDelCount=0
[junit4] 2> 89452 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes took 0 msec
[junit4] 2> 89452 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 _1(5.0.0):C1 minGen=10 packetCount=1
[junit4] 2> 89453 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89453 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89453 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: findMerges: 2 segments
[junit4] 2> 89453 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: seg=_0(5.0.0):C10 size=0.002 MB [floored]
[junit4] 2> 89454 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: seg=_1(5.0.0):C1 size=0.001 MB [floored]
[junit4] 2> 89454 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: allowedSegmentCount=1 vs count=2 (eligible count=2) tooBigCount=0
[junit4] 2> 89454 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: now merge
[junit4] 2> 89454 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: index: _0(5.0.0):C10 _1(5.0.0):C1
[junit4] 2> 89455 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: no more merges pending; now return
[junit4] 2> 89455 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit(): start
[junit4] 2> 89455 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit index=_0(5.0.0):C10 _1(5.0.0):C1 changeCount=6
[junit4] 2> 89456 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: done all syncs: [_0.nvm, _0.fdx, _1.si, _1_Lucene50_0.tim, _1_Lucene50_0.doc, _1.fnm, _0_Lucene50_0.tim, _0_Lucene50_0.tip, _0.si, _0_Lucene50_0.pos, _0.fnm, _0.nvd, _1_Lucene50_0.tip, _0.fdt, _1.fdt, _1.fdx, _0_Lucene50_0.doc]
[junit4] 2> 89456 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: pendingCommit != null
[junit4] 2> 89456 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _1(5.0.0):C1" [2 segments ; isCommit = true]
[junit4] 2> 89456 T115 C15 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_3,generation=3}
[junit4] 2> 89457 T115 C15 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 89457 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 89457 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: delete "segments_2"
[junit4] 2> 89457 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 1 msec to checkpoint
[junit4] 2> 89458 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: wrote segments file "segments_3"
[junit4] 2> 89458 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: took 11.1 msec
[junit4] 2> 89458 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: done
[junit4] 2> 89458 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 89459 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: flush at getReader
[junit4] 2> 89459 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89459 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89459 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: no deletes; skipping
[junit4] 2> 89459 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 _1(5.0.0):C1 minGen=10 packetCount=0
[junit4] 2> 89460 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: return reader version=5 reader=StandardDirectoryReader(segments_1:5:nrt _0(5.0.0):C10 _1(5.0.0):C1)
[junit4] 2> 89461 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89461 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: getReader took 2 msec
[junit4] 2> 89461 T115 C15 oass.SolrIndexSearcher.<init> Opening Searcher@4456bdfe[collection1] main
[junit4] 2> 89462 T115 C15 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89462 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@4456bdfe[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10) Uninverting(_1(5.0.0):C1)))}
[junit4] 2> 89462 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89462 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4456bdfe[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10) Uninverting(_1(5.0.0):C1)))}
[junit4] 2> 89463 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&softCommit=false&wt=javabin&commit=true&waitSearcher=true} {commit=} 0 17
[junit4] 2> 89468 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&wt=javabin} {add=[testSetNullUpdates (1487034325508554752)]} 0 2
[junit4] 2> 89472 T115 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89472 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: start
[junit4] 2> 89472 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: enter lock
[junit4] 2> 89472 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: now prepare
[junit4] 2> 89473 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: prepareCommit: flush
[junit4] 2> 89473 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: index before flush _0(5.0.0):C10 _1(5.0.0):C1
[junit4] 2> 89473 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89473 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89473 T115 C15 oasu.LoggingInfoStream.message [DWFC][qtp557502298-115]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborted=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 6 ]]
[junit4] 2> 89474 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flush postings as segment _2 numDocs=1
[junit4] 2> 89475 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has 0 deleted docs
[junit4] 2> 89475 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 89475 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushedFiles=[_2.fdt, _2_Lucene50_0.tim, _2_Lucene50_0.doc, _2_Lucene50_0.tip, _2.fnm, _2.fdx]
[junit4] 2> 89475 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed codec=Lucene50
[junit4] 2> 89476 T115 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-115]: flushed: segment=_2 ramUsed=0.087 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=927.943
[junit4] 2> 89476 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: publishFlushedSegment seg-private updates=null
[junit4] 2> 89476 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publishFlushedSegment
[junit4] 2> 89476 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: push deletes 1 deleted terms (unique count=1) bytesUsed=1056 delGen=12 packetCount=1 totBytesUsed=1056
[junit4] 2> 89477 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: publish sets newSegment delGen=13 seg=_2(5.0.0):C1
[junit4] 2> 89477 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _1(5.0.0):C1 _2(5.0.0):C1" [3 segments ; isCommit = false]
[junit4] 2> 89477 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89477 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89478 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: infos=[_0(5.0.0):C10, _1(5.0.0):C1, _2(5.0.0):C1] packetCount=1
[junit4] 2> 89478 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: seg=_1(5.0.0):C1 segGen=10 coalesced deletes=[CoalescedUpdates(termSets=1,queries=0,numericDVUpdates=0,binaryDVUpdates=0)] newDelCount=1 100% deleted
[junit4] 2> 89478 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: seg=_0(5.0.0):C10 segGen=10 coalesced deletes=[CoalescedUpdates(termSets=1,queries=0,numericDVUpdates=0,binaryDVUpdates=0)] newDelCount=0
[junit4] 2> 89478 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes took 0 msec
[junit4] 2> 89479 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _1(5.0.0):C1/1 _2(5.0.0):C1" [3 segments ; isCommit = false]
[junit4] 2> 89479 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89479 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: drop 100% deleted segments: _1(5.0.0):C1/1
[junit4] 2> 89479 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _2(5.0.0):C1" [2 segments ; isCommit = false]
[junit4] 2> 89480 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89480 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 _2(5.0.0):C1 minGen=14 packetCount=1
[junit4] 2> 89480 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89480 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89481 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: findMerges: 2 segments
[junit4] 2> 89481 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: seg=_0(5.0.0):C10 size=0.002 MB [floored]
[junit4] 2> 89481 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: seg=_2(5.0.0):C1 size=0.001 MB [floored]
[junit4] 2> 89481 T115 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-115]: allowedSegmentCount=1 vs count=2 (eligible count=2) tooBigCount=0
[junit4] 2> 89482 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: now merge
[junit4] 2> 89482 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: index: _0(5.0.0):C10 _2(5.0.0):C1
[junit4] 2> 89482 T115 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-115]: no more merges pending; now return
[junit4] 2> 89482 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit(): start
[junit4] 2> 89482 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit index=_0(5.0.0):C10 _2(5.0.0):C1 changeCount=11
[junit4] 2> 89483 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: done all syncs: [_0.nvm, _0.fdx, _2_Lucene50_0.tim, _0_Lucene50_0.tim, _0_Lucene50_0.tip, _0.si, _0_Lucene50_0.pos, _0.fnm, _0.nvd, _2.fdt, _0.fdt, _2_Lucene50_0.doc, _2_Lucene50_0.tip, _2.fnm, _2.si, _2.fdx, _0_Lucene50_0.doc]
[junit4] 2> 89483 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: pendingCommit != null
[junit4] 2> 89483 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10 _2(5.0.0):C1" [2 segments ; isCommit = true]
[junit4] 2> 89484 T115 C15 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_4,generation=4}
[junit4] 2> 89484 T115 C15 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 89484 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 89484 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: delete "segments_3"
[junit4] 2> 89485 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 1 msec to checkpoint
[junit4] 2> 89485 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: wrote segments file "segments_4"
[junit4] 2> 89485 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: took 12.4 msec
[junit4] 2> 89485 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: done
[junit4] 2> 89486 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 89486 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: flush at getReader
[junit4] 2> 89486 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89486 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89486 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: no deletes; skipping
[junit4] 2> 89487 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: _0(5.0.0):C10 _2(5.0.0):C1 minGen=14 packetCount=0
[junit4] 2> 89487 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: return reader version=9 reader=StandardDirectoryReader(segments_1:9:nrt _0(5.0.0):C10 _2(5.0.0):C1)
[junit4] 2> 89488 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89488 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: getReader took 2 msec
[junit4] 2> 89488 T115 C15 oass.SolrIndexSearcher.<init> Opening Searcher@16f8468e[collection1] main
[junit4] 2> 89489 T115 C15 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89489 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@16f8468e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10) Uninverting(_2(5.0.0):C1)))}
[junit4] 2> 89489 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89489 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16f8468e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(5.0.0):C10) Uninverting(_2(5.0.0):C1)))}
[junit4] 2> 89490 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1.si"
[junit4] 2> 89490 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1_Lucene50_0.tim"
[junit4] 2> 89490 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1_Lucene50_0.doc"
[junit4] 2> 89490 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1.fnm"
[junit4] 2> 89491 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1_Lucene50_0.tip"
[junit4] 2> 89491 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1.fdt"
[junit4] 2> 89491 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_1.fdx"
[junit4] 2> 89491 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&softCommit=false&wt=javabin&commit=true&waitSearcher=true} {commit=} 0 19
[junit4] 2> 89494 T115 C15 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={version=2&wt=javabin&q=id:testSetNullUpdates} hits=1 status=0 QTime=0
[junit4] 2> 89495 T112 oas.SolrTestCaseJ4.tearDown ###Ending testSetNullUpdates
[junit4] 2> 89503 T112 oas.SolrTestCaseJ4.setUp ###Starting testArbitraryJsonIndexing
[junit4] 2> 89506 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89506 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89507 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 89507 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: flush at getReader
[junit4] 2> 89507 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89507 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89508 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115: flush naked frozen global deletes
[junit4] 2> 89508 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: push deletes 1 deleted queries bytesUsed=64 delGen=16 packetCount=1 totBytesUsed=64
[junit4] 2> 89508 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: flush: push buffered updates: 1 deleted queries bytesUsed=64
[junit4] 2> 89508 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89509 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes: infos=[_0(5.0.0):C10, _2(5.0.0):C1] packetCount=1
[junit4] 2> 89509 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: seg=_2(5.0.0):C1 segGen=14 coalesced deletes=[CoalescedUpdates(termSets=1,queries=1,numericDVUpdates=0,binaryDVUpdates=0)] newDelCount=1 100% deleted
[junit4] 2> 89510 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: seg=_0(5.0.0):C10 segGen=14 coalesced deletes=[CoalescedUpdates(termSets=1,queries=1,numericDVUpdates=0,binaryDVUpdates=0)] newDelCount=10 100% deleted
[junit4] 2> 89510 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: applyDeletes took 1 msec
[junit4] 2> 89510 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "_0(5.0.0):C10/10 _2(5.0.0):C1/1" [2 segments ; isCommit = false]
[junit4] 2> 89511 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89511 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: drop 100% deleted segments: _2(5.0.0):C1/1 _0(5.0.0):C10/10
[junit4] 2> 89511 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 89512 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 0 msec to checkpoint
[junit4] 2> 89512 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: minGen=9223372036854775807 packetCount=1
[junit4] 2> 89512 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89512 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: return reader version=11 reader=StandardDirectoryReader(segments_1:11:nrt)
[junit4] 2> 89513 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89513 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: getReader took 6 msec
[junit4] 2> 89513 T115 C15 oass.SolrIndexSearcher.<init> Opening Searcher@3480a546[collection1] realtime
[junit4] 2> 89514 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1487034325549449216)} 0 9
[junit4] 2> 89517 T115 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89517 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: start
[junit4] 2> 89517 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: enter lock
[junit4] 2> 89518 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: now prepare
[junit4] 2> 89518 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: prepareCommit: flush
[junit4] 2> 89518 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: index before flush
[junit4] 2> 89518 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: startFullFlush
[junit4] 2> 89519 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: apply all deletes during flush
[junit4] 2> 89519 T115 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-115]: prune sis=segments_1: minGen=9223372036854775807 packetCount=0
[junit4] 2> 89519 T115 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-115]: qtp557502298-115 finishFullFlush success=true
[junit4] 2> 89519 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit(): start
[junit4] 2> 89519 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: startCommit index= changeCount=14
[junit4] 2> 89520 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: done all syncs: []
[junit4] 2> 89520 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: pendingCommit != null
[junit4] 2> 89520 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 89521 T115 C15 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_5,generation=5}
[junit4] 2> 89521 T115 C15 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 89521 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 89521 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: delete "segments_4"
[junit4] 2> 89522 T115 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-115]: 1 msec to checkpoint
[junit4] 2> 89522 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: wrote segments file "segments_5"
[junit4] 2> 89522 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: took 4.2 msec
[junit4] 2> 89522 T115 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-115]: commit: done
[junit4] 2> 89523 T115 C15 oass.SolrIndexSearcher.<init> Opening Searcher@7cccf31c[collection1] main
[junit4] 2> 89523 T115 C15 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89523 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@7cccf31c[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 89524 T123 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89524 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7cccf31c[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 89524 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.nvm"
[junit4] 2> 89524 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.fdx"
[junit4] 2> 89525 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2_Lucene50_0.tim"
[junit4] 2> 89525 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0_Lucene50_0.tim"
[junit4] 2> 89525 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0_Lucene50_0.tip"
[junit4] 2> 89525 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.si"
[junit4] 2> 89525 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0_Lucene50_0.pos"
[junit4] 2> 89526 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.fnm"
[junit4] 2> 89526 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.nvd"
[junit4] 2> 89526 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2.fdt"
[junit4] 2> 89526 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0.fdt"
[junit4] 2> 89526 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2_Lucene50_0.doc"
[junit4] 2> 89527 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2_Lucene50_0.tip"
[junit4] 2> 89527 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2.fnm"
[junit4] 2> 89527 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2.si"
[junit4] 2> 89527 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_2.fdx"
[junit4] 2> 89527 T123 oasu.LoggingInfoStream.message [IFD][searcherExecutor-76-thread-1]: delete "_0_Lucene50_0.doc"
[junit4] 2> 89528 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2&softCommit=false&wt=javabin&commit=true&waitSearcher=true} {commit=} 0 11
[junit4] 2> 89530 T115 C15 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={version=2&wt=javabin&q=*:*} hits=0 status=0 QTime=0
[junit4] 2> 89556 T115 C15 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update/json/docs params={} {add=[abc1 (1487034325600829440), 452215e8-e726-4e5c-87e3-18a94e9f80a4 (1487034325602926592)]} 0 23
[junit4] 2> 89565 T116 C15 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89566 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: start
[junit4] 2> 89566 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: enter lock
[junit4] 2> 89566 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: now prepare
[junit4] 2> 89566 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: prepareCommit: flush
[junit4] 2> 89567 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: index before flush
[junit4] 2> 89567 T116 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-116]: startFullFlush
[junit4] 2> 89567 T116 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-116]: anyChanges? numDocsInRam=2 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89567 T116 C15 oasu.LoggingInfoStream.message [DWFC][qtp557502298-116]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 1 deleted terms (unique count=1) bytesUsed=200, segment=_3, aborted=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 10 ]]
[junit4] 2> 89568 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: flush postings as segment _3 numDocs=2
[junit4] 2> 89570 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: new segment has 0 deleted docs
[junit4] 2> 89570 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 89571 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: flushedFiles=[_3_Lucene50_0.doc, _3_Lucene50_0.tim, _3.fnm, _3_Lucene50_0.pos, _3.fdt, _3.nvm, _3_Lucene50_0.tip, _3.fdx, _3.nvd]
[junit4] 2> 89571 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: flushed codec=Lucene50
[junit4] 2> 89571 T116 C15 oasu.LoggingInfoStream.message [DWPT][qtp557502298-116]: flushed: segment=_3 ramUsed=0.087 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,400.903
[junit4] 2> 89572 T116 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-116]: publishFlushedSegment seg-private updates=null
[junit4] 2> 89572 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: publishFlushedSegment
[junit4] 2> 89572 T116 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-116]: push deletes 2 deleted terms (unique count=2) bytesUsed=1056 delGen=19 packetCount=1 totBytesUsed=1056
[junit4] 2> 89573 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: publish sets newSegment delGen=20 seg=_3(5.0.0):C2
[junit4] 2> 89573 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: now checkpoint "_3(5.0.0):C2" [1 segments ; isCommit = false]
[junit4] 2> 89574 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: 0 msec to checkpoint
[junit4] 2> 89574 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: apply all deletes during flush
[junit4] 2> 89574 T116 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-116]: applyDeletes: infos=[_3(5.0.0):C2] packetCount=1
[junit4] 2> 89575 T116 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-116]: applyDeletes took 1 msec
[junit4] 2> 89575 T116 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-116]: prune sis=segments_1: _3(5.0.0):C2 minGen=21 packetCount=1
[junit4] 2> 89575 T116 C15 oasu.LoggingInfoStream.message [BD][qtp557502298-116]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89576 T116 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-116]: qtp557502298-116 finishFullFlush success=true
[junit4] 2> 89576 T116 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-116]: findMerges: 1 segments
[junit4] 2> 89576 T116 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-116]: seg=_3(5.0.0):C2 size=0.001 MB [floored]
[junit4] 2> 89577 T116 C15 oasu.LoggingInfoStream.message [TMP][qtp557502298-116]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 89577 T116 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-116]: now merge
[junit4] 2> 89577 T116 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-116]: index: _3(5.0.0):C2
[junit4] 2> 89578 T116 C15 oasu.LoggingInfoStream.message [CMS][qtp557502298-116]: no more merges pending; now return
[junit4] 2> 89578 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: startCommit(): start
[junit4] 2> 89578 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: startCommit index=_3(5.0.0):C2 changeCount=17
[junit4] 2> 89579 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: done all syncs: [_3.fnm, _3_Lucene50_0.tim, _3_Lucene50_0.doc, _3.si, _3_Lucene50_0.pos, _3.fdt, _3_Lucene50_0.tip, _3.nvm, _3.fdx, _3.nvd]
[junit4] 2> 89579 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: pendingCommit != null
[junit4] 2> 89580 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: now checkpoint "_3(5.0.0):C2" [1 segments ; isCommit = true]
[junit4] 2> 89580 T116 C15 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_5,generation=5}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@765c165c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@17c02eb9),segFN=segments_6,generation=6}
[junit4] 2> 89580 T116 C15 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4] 2> 89581 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: deleteCommits: now decRef commit "segments_5"
[junit4] 2> 89581 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: delete "segments_5"
[junit4] 2> 89581 T116 C15 oasu.LoggingInfoStream.message [IFD][qtp557502298-116]: 1 msec to checkpoint
[junit4] 2> 89582 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: wrote segments file "segments_6"
[junit4] 2> 89582 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: took 15.6 msec
[junit4] 2> 89582 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: commit: done
[junit4] 2> 89583 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 89583 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: flush at getReader
[junit4] 2> 89583 T116 C15 oasu.LoggingInfoStream.message [DW][qtp557502298-116]: startFullFlush
[junit4] 2> 89584 T116 C15 oasu.LoggingInfoStream.message [IW][qtp557502298-116]: apply all deletes during flush
[junit4] 2> 89584 T116 C15 oasu.LoggingInfoStream.message [BD][
[...truncated too long message...]
InfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: index before flush _1c(5.0.0):C2
[junit4] 2> 96419 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: startFullFlush
[junit4] 2> 96420 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker finishFullFlush success=true
[junit4] 2> 96420 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: apply all deletes during flush
[junit4] 2> 96420 T112 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 96421 T112 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: prune sis=segments_1: _1c(5.0.0):C2 minGen=288 packetCount=0
[junit4] 2> 96421 T112 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: now merge
[junit4] 2> 96421 T112 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: index: _1c(5.0.0):C2
[junit4] 2> 96422 T112 C17 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: no more merges pending; now return
[junit4] 2> 96422 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: waitForMerges
[junit4] 2> 96422 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: waitForMerges done
[junit4] 2> 96423 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: start
[junit4] 2> 96423 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: enter lock
[junit4] 2> 96423 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: now prepare
[junit4] 2> 96423 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: prepareCommit: flush
[junit4] 2> 96424 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: index before flush _1c(5.0.0):C2
[junit4] 2> 96424 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: startFullFlush
[junit4] 2> 96424 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: apply all deletes during flush
[junit4] 2> 96425 T112 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 96425 T112 C17 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: prune sis=segments_1: _1c(5.0.0):C2 minGen=288 packetCount=0
[junit4] 2> 96425 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker finishFullFlush success=true
[junit4] 2> 96426 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: startCommit(): start
[junit4] 2> 96426 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: skip startCommit(): no changes pending
[junit4] 2> 96426 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 96427 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: wrote segments file "null"
[junit4] 2> 96427 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: took 3.5 msec
[junit4] 2> 96427 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: commit: done
[junit4] 2> 96428 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: rollback
[junit4] 2> 96428 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: all running merges have aborted
[junit4] 2> 96428 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: rollback: done finish merges
[junit4] 2> 96429 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: abort
[junit4] 2> 96429 T112 C17 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: done abort success=true
[junit4] 2> 96429 T112 C17 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: rollback: infos=_1c(5.0.0):C2
[junit4] 2> 96430 T112 C17 oasu.LoggingInfoStream.message [IFD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: now checkpoint "_1c(5.0.0):C2" [1 segments ; isCommit = false]
[junit4] 2> 96430 T112 C17 oasu.LoggingInfoStream.message [IFD][SUITE-SolrExampleJettyTest-seed#[9899A23A4DB4B301]-worker]: 0 msec to checkpoint
[junit4] 2> 96431 T112 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 96431 T112 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 96432 T112 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002 [CachedDir<<refCount=0;path=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002;done=false>>]
[junit4] 2> 96432 T112 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002
[junit4] 2> 96432 T112 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index [CachedDir<<refCount=0;path=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index;done=false>>]
[junit4] 2> 96433 T112 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001/tempDir-002/index
[junit4] 2> 96433 T112 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 101418 T112 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.embedded.SolrExampleJettyTest-9899A23A4DB4B301-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene50): {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=el_GR, timezone=Australia/Perth
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_65 (64-bit)/cpus=16,threads=1,free=195240272,total=277872640
[junit4] 2> NOTE: All tests run in this JVM: [TestJsonRecordReader, TestSolrProperties, TestSpellCheckResponse, LargeVolumeBinaryJettyTest, TestJavaBinCodec, TermsResponseTest, SolrParamTest, SolrExampleStreamingTest, SolrExampleXMLTest, SolrExampleJettyTest]
[junit4] Completed on J2 in 13.57s, 32 tests, 1 error <<< FAILURES!
[...truncated 87 lines...]
BUILD FAILED
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/build.xml:529: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/build.xml:477: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/build.xml:61: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/extra-targets.xml:39: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/build.xml:203: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/solr/common-build.xml:508: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/lucene/common-build.xml:1363: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-5.x-Java7/lucene/common-build.xml:970: There were test failures: 54 suites, 332 tests, 1 error
Total time: 64 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-Tests-5.x-Java7 #2301
Archived 5 artifacts
Archive block size is 32768
Received 0 blocks and 11045089 bytes
Compression is 0.0%
Took 2.7 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure