You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/08/31 00:46:46 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 758 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/758/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.TestBatchUpdate.testWithXml
Error Message:
IOException occured when talking to server at: https://127.0.0.1:54960/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:54960/solr/collection1
at __randomizedtesting.SeedInfo.seed([214AB201C1076AE1:8AA80BF74301738C]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
at org.apache.solr.client.solrj.TestBatchUpdate.doIt(TestBatchUpdate.java:130)
at org.apache.solr.client.solrj.TestBatchUpdate.testWithXml(TestBatchUpdate.java:54)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 46 more
Build Log:
[...truncated 11023 lines...]
[junit4] Suite: org.apache.solr.client.solrj.TestBatchUpdate
[junit4] 2> 121087 T251 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 121088 T251 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-TestBatchUpdate-1377902431336
[junit4] 2> 121091 T251 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 121141 T251 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 121720 T251 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 121732 T251 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:54960
[junit4] 2> 121737 T251 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 121739 T251 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 121739 T251 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 121740 T251 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/'
[junit4] 2> 121820 T251 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 122024 T251 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 122026 T251 oasc.CoreContainer.<init> New CoreContainer 1090018507
[junit4] 2> 122027 T251 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/]
[junit4] 2> 122033 T251 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 122034 T251 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 122035 T251 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 122036 T251 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 122037 T251 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 122037 T251 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 122038 T251 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 122039 T251 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 122039 T251 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 122040 T251 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 122052 T251 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 122053 T251 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 122063 T251 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 122093 T251 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/
[junit4] 2> 122097 T251 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 122099 T261 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1
[junit4] 2> 122101 T261 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 122152 T261 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 122154 T261 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 122154 T261 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 122156 T261 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 122156 T261 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 122157 T261 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 122158 T261 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 122159 T261 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 122160 T261 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 122276 T261 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 122282 T261 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 122576 T261 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 122577 T261 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 122619 T261 oass.IndexSchema.readSchema [null] Schema name=example
[junit4] 2> 124970 T261 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 125034 T261 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 125045 T261 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 125102 T261 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 125103 T261 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/
[junit4] 2> 125104 T261 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@432b198d
[junit4] 2> 125105 T261 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 125106 T261 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 125107 T261 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336
[junit4] 2> 125108 T261 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index/
[junit4] 2> 125108 T261 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index' doesn't exist. Creating new index...
[junit4] 2> 125109 T261 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index
[junit4] 2> 125112 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@3b348009
[junit4] 2> 125113 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 125113 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: 0 msec to checkpoint
[junit4] 2> 125114 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: init: create=true
[junit4] 2> 125115 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@73c1ed3c
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 125115 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 125116 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 125117 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: index before flush
[junit4] 2> 125117 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 startFullFlush
[junit4] 2> 125118 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125119 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 finishFullFlush success=true
[junit4] 2> 125119 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: apply all deletes during flush
[junit4] 2> 125120 T261 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-150-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@40be3983 minGen=9223372036854775807 packetCount=0
[junit4] 2> 125121 T261 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-150-thread-1]: now merge
[junit4] 2> 125122 T261 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-150-thread-1]: index:
[junit4] 2> 125122 T261 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-150-thread-1]: no more merges pending; now return
[junit4] 2> 125123 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: waitForMerges
[junit4] 2> 125123 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: waitForMerges done
[junit4] 2> 125124 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: now call final commit()
[junit4] 2> 125124 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: start
[junit4] 2> 125125 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: enter lock
[junit4] 2> 125126 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: now prepare
[junit4] 2> 125126 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: prepareCommit: flush
[junit4] 2> 125126 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: index before flush
[junit4] 2> 125127 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 startFullFlush
[junit4] 2> 125127 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125128 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: apply all deletes during flush
[junit4] 2> 125128 T261 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-150-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@40be3983 minGen=9223372036854775807 packetCount=0
[junit4] 2> 125129 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 finishFullFlush success=true
[junit4] 2> 125130 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: startCommit(): start
[junit4] 2> 125130 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: startCommit index= changeCount=1
[junit4] 2> 125131 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: done all syncs: []
[junit4] 2> 125131 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: pendingCommit != null
[junit4] 2> 125132 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 125133 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 125133 T261 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_1,generation=1}
[junit4] 2> 125134 T261 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 125134 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: 1 msec to checkpoint
[junit4] 2> 125135 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: commit: done
[junit4] 2> 125135 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: at close:
[junit4] 2> 125137 T261 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 125138 T261 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 125138 T261 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 125139 T261 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 125139 T261 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 125151 T261 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 125153 T261 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 125154 T261 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 125155 T261 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 125157 T261 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 125158 T261 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 125159 T261 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 125159 T261 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 125160 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 125160 T261 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 125161 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 125161 T261 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 125162 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 125162 T261 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 125163 T261 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 125163 T261 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 125164 T261 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 125165 T261 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 125165 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 125166 T261 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 125167 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 125168 T261 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 125169 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 125169 T261 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 125170 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 125170 T261 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 125171 T261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 125172 T261 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 125186 T261 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 125189 T261 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 125191 T261 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 125202 T261 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 125202 T261 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 125205 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@3b348009
[junit4] 2> 125205 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: init: load commit "segments_1"
[junit4] 2> 125206 T261 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_1,generation=1}
[junit4] 2> 125206 T261 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 125207 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 125207 T261 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-150-thread-1]: 0 msec to checkpoint
[junit4] 2> 125207 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: init: create=false
[junit4] 2> 125208 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@3a26b9fa
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 125208 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: flush at getReader
[junit4] 2> 125209 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 startFullFlush
[junit4] 2> 125210 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125212 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: apply all deletes during flush
[junit4] 2> 125213 T261 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-150-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=9223372036854775807 packetCount=0
[junit4] 2> 125213 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 125213 T261 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-150-thread-1]: coreLoadExecutor-150-thread-1 finishFullFlush success=true
[junit4] 2> 125214 T261 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-150-thread-1]: getReader took 6 msec
[junit4] 2> 125214 T261 oass.SolrIndexSearcher.<init> Opening Searcher@2d6e1a4a main
[junit4] 2> 125215 T261 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 125215 T261 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> 125216 T261 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 125217 T261 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 125288 T261 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 125289 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@2d6e1a4a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C26 name=collection1 org.apache.solr.core.SolrCore@14c03d92
[junit4] 2> 125291 T262 C26 oasc.SolrCore.execute [collection1] webapp=null path=null params={event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml&distrib=false} hits=0 status=0 QTime=1
[junit4] 2> 125292 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 125292 T262 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 125292 T262 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 125319 T262 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d6e1a4a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 125322 T261 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 125324 T251 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 125325 T251 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 125325 T251 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#54960
[junit4] 2> 125336 T251 oas.SolrTestCaseJ4.setUp ###Starting testWithXml
[junit4] 2> 125338 T251 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C27 name=collection1 org.apache.solr.core.SolrCore@14c03d92
[junit4] 2> 125671 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125672 T256 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-256]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 125674 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125675 T256 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-256]: flush at getReader
[junit4] 2> 125676 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: qtp294255203-256 startFullFlush
[junit4] 2> 125678 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 125680 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: qtp294255203-256: flush naked frozen global deletes
[junit4] 2> 125682 T256 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-256]: push deletes 1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
[junit4] 2> 125684 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 125685 T256 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-256]: apply all deletes during flush
[junit4] 2> 125686 T256 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-256]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=9223372036854775807 packetCount=1
[junit4] 2> 125686 T256 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-256]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 125687 T256 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-256]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 125688 T256 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-256]: qtp294255203-256 finishFullFlush success=true
[junit4] 2> 125689 T256 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-256]: getReader took 14 msec
[junit4] 2> 125691 T256 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444835424640958464)} 0 25
[junit4] 2> 127340 T258 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1 (1444835424773079040), 2 (1444835424794050560), 3 (1444835424795099136), 4 (1444835424796147712), 5 (1444835424797196288), 6 (1444835424797196289), 7 (1444835424798244864), 8 (1444835424799293440), 9 (1444835424800342016), 10 (1444835424800342017), ... (1000 adds)]} 0 1547
[junit4] 2> 140692 T264 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 140693 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: start
[junit4] 2> 140693 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: enter lock
[junit4] 2> 140693 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: now prepare
[junit4] 2> 140693 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: prepareCommit: flush
[junit4] 2> 140694 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: index before flush
[junit4] 2> 140694 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: commitScheduler-153-thread-1 startFullFlush
[junit4] 2> 140694 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: anyChanges? numDocsInRam=1000 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 140695 T264 oasu.LoggingInfoStream.message [DWFC][commitScheduler-153-thread-1]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 999 deleted terms (unique count=999) bytesUsed=166728, segment=_0, aborting=false, numDocsInRAM=1000, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 140717 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: flush postings as segment _0 numDocs=1000
[junit4] 2> 140859 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: new segment has 0 deleted docs
[junit4] 2> 140859 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 140860 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.nvm, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4] 2> 140861 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: flushed codec=Lucene45
[junit4] 2> 140889 T264 oasu.LoggingInfoStream.message [DWPT][commitScheduler-153-thread-1]: flushed: segment=_0 ramUsed=0.286 MB newFlushedSize(includes docstores)=0.024 MB docs/MB=41,906.163
[junit4] 2> 140890 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 140891 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: publishFlushedSegment
[junit4] 2> 140891 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: push deletes 1000 deleted terms (unique count=1000) bytesUsed=3072 delGen=4 packetCount=1 totBytesUsed=3072
[junit4] 2> 140891 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: publish sets newSegment delGen=5 seg=_0(4.5):C1000
[junit4] 2> 140892 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: now checkpoint "_0(4.5):C1000" [1 segments ; isCommit = false]
[junit4] 2> 140892 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: 0 msec to checkpoint
[junit4] 2> 140892 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: apply all deletes during flush
[junit4] 2> 140893 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: applyDeletes: infos=[_0(4.5):C1000] packetCount=1
[junit4] 2> 140893 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: applyDeletes took 0 msec
[junit4] 2> 140894 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=6 packetCount=1
[junit4] 2> 140895 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 140895 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: commitScheduler-153-thread-1 finishFullFlush success=true
[junit4] 2> 140895 T264 oasu.LoggingInfoStream.message [TMP][commitScheduler-153-thread-1]: findMerges: 1 segments
[junit4] 2> 140896 T264 oasu.LoggingInfoStream.message [TMP][commitScheduler-153-thread-1]: seg=_0(4.5):C1000 size=0.023 MB [floored]
[junit4] 2> 140896 T264 oasu.LoggingInfoStream.message [TMP][commitScheduler-153-thread-1]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 140897 T264 oasu.LoggingInfoStream.message [CMS][commitScheduler-153-thread-1]: now merge
[junit4] 2> 140897 T264 oasu.LoggingInfoStream.message [CMS][commitScheduler-153-thread-1]: index: _0(4.5):C1000
[junit4] 2> 140897 T264 oasu.LoggingInfoStream.message [CMS][commitScheduler-153-thread-1]: no more merges pending; now return
[junit4] 2> 140898 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: startCommit(): start
[junit4] 2> 140898 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: startCommit index=_0(4.5):C1000 changeCount=3
[junit4] 2> 140903 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4] 2> 140904 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: pendingCommit != null
[junit4] 2> 140904 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: wrote segments file "segments_2"
[junit4] 2> 140905 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: now checkpoint "_0(4.5):C1000" [1 segments ; isCommit = true]
[junit4] 2> 140905 T264 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_2,generation=2}
[junit4] 2> 140906 T264 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 140907 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 140907 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: delete "segments_1"
[junit4] 2> 140907 T264 oasu.LoggingInfoStream.message [IFD][commitScheduler-153-thread-1]: 2 msec to checkpoint
[junit4] 2> 140908 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: commit: done
[junit4] 2> 140909 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 140920 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 140921 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: flush at getReader
[junit4] 2> 140921 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: commitScheduler-153-thread-1 startFullFlush
[junit4] 2> 140922 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 140922 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: apply all deletes during flush
[junit4] 2> 140923 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: applyDeletes: no deletes; skipping
[junit4] 2> 140923 T264 oasu.LoggingInfoStream.message [BD][commitScheduler-153-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=6 packetCount=0
[junit4] 2> 140925 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1000)
[junit4] 2> 140926 T264 oasu.LoggingInfoStream.message [DW][commitScheduler-153-thread-1]: commitScheduler-153-thread-1 finishFullFlush success=true
[junit4] 2> 140926 T264 oasu.LoggingInfoStream.message [IW][commitScheduler-153-thread-1]: getReader took 5 msec
[junit4] 2> 140926 T264 oass.SolrIndexSearcher.<init> Opening Searcher@95258f0 realtime
[junit4] 2> 140927 T264 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 327666 T259 C27 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 327667 T259 C27 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 327666 T251 oas.SolrTestCaseJ4.tearDown ###Ending testWithXml
[junit4] 2> 327667 T259 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-259]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 327668 T259 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-259]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 327669 T259 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-259]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 327669 T259 C27 oass.SolrIndexSearcher.<init> Opening Searcher@59d8afee main
[junit4] 2> 327671 T259 C27 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 327671 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@59d8afee main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1000)}
[junit4] 2> 327672 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 327675 T262 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@59d8afee main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1000)}
[junit4] 2> 327676 T259 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestBatchUpdate -Dtests.method=testWithXml -Dtests.seed=214AB201C1076AE1 -Dtests.slow=true -Dtests.locale=es_PA -Dtests.timezone=Europe/Dublin -Dtests.file.encoding=US-ASCII
[junit4] ERROR 203s | TestBatchUpdate.testWithXml <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:54960/solr/collection1
[junit4] > at __randomizedtesting.SeedInfo.seed([214AB201C1076AE1:8AA80BF74301738C]:0)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4] > at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4] > at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
[junit4] > at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
[junit4] > at org.apache.solr.client.solrj.TestBatchUpdate.doIt(TestBatchUpdate.java:130)
[junit4] > at org.apache.solr.client.solrj.TestBatchUpdate.testWithXml(TestBatchUpdate.java:54)
[junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4] > Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
[junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
[junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
[junit4] > at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
[junit4] > at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
[junit4] > at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
[junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
[junit4] > at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
[junit4] > at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
[junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
[junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
[junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4] > ... 46 more
[junit4] 2> 327844 T251 oas.SolrTestCaseJ4.setUp ###Starting testWithBinaryBean
[junit4] 2> 327897 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 327898 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 327898 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 327899 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: flush at getReader
[junit4] 2> 327899 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255 startFullFlush
[junit4] 2> 327900 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 327900 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255: flush naked frozen global deletes
[junit4] 2> 327901 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: push deletes 1 deleted queries bytesUsed=32 delGen=8 packetCount=1 totBytesUsed=32
[junit4] 2> 327901 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 327902 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: apply all deletes during flush
[junit4] 2> 327902 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: applyDeletes: infos=[_0(4.5):C1000] packetCount=1
[junit4] 2> 327919 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: seg=_0(4.5):C1000 segGen=6 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1000 100% deleted
[junit4] 2> 327920 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: applyDeletes took 18 msec
[junit4] 2> 327920 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: now checkpoint "_0(4.5):C1000/1000" [1 segments ; isCommit = false]
[junit4] 2> 327921 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: 0 msec to checkpoint
[junit4] 2> 327921 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: drop 100% deleted segments: _0(4.5):C1000/1000
[junit4] 2> 327923 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 327924 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: 1 msec to checkpoint
[junit4] 2> 327924 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=9223372036854775807 packetCount=1
[junit4] 2> 327925 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 327926 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 327926 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255 finishFullFlush success=true
[junit4] 2> 327927 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: getReader took 28 msec
[junit4] 2> 327927 T255 C27 oass.SolrIndexSearcher.<init> Opening Searcher@46a5227 realtime
[junit4] 2> 327928 T255 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444835636693434368)} 0 39
[junit4] 2> 328768 T257 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1 (1444835636811923456), 2 (1444835636814020608), 3 (1444835636815069184), 4 (1444835636815069185), 5 (1444835636816117760), 6 (1444835636816117761), 7 (1444835636816117762), 8 (1444835636817166336), 9 (1444835636817166337), 10 (1444835636818214912), ... (1000 adds)]} 0 760
[junit4] 2> 328779 T258 C27 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 328780 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: start
[junit4] 2> 328781 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: enter lock
[junit4] 2> 328782 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: now prepare
[junit4] 2> 328782 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: prepareCommit: flush
[junit4] 2> 328782 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: index before flush
[junit4] 2> 328783 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 startFullFlush
[junit4] 2> 328783 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=1000 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328784 T258 C27 oasu.LoggingInfoStream.message [DWFC][qtp294255203-258]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 999 deleted terms (unique count=999) bytesUsed=166728, segment=_1, aborting=false, numDocsInRAM=1000, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 328791 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flush postings as segment _1 numDocs=1000
[junit4] 2> 328808 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: new segment has 0 deleted docs
[junit4] 2> 328809 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 328809 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushedFiles=[_1.nvm, _1_Lucene41_0.pos, _1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 328810 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushed codec=Lucene45
[junit4] 2> 328810 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushed: segment=_1 ramUsed=0.286 MB newFlushedSize(includes docstores)=0.024 MB docs/MB=42,040.574
[junit4] 2> 328811 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 328812 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: publishFlushedSegment
[junit4] 2> 328812 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: push deletes 1000 deleted terms (unique count=1000) bytesUsed=3072 delGen=10 packetCount=1 totBytesUsed=3072
[junit4] 2> 328814 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: publish sets newSegment delGen=11 seg=_1(4.5):C1000
[junit4] 2> 328814 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: now checkpoint "_1(4.5):C1000" [1 segments ; isCommit = false]
[junit4] 2> 328815 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: 0 msec to checkpoint
[junit4] 2> 328815 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: apply all deletes during flush
[junit4] 2> 328816 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes: infos=[_1(4.5):C1000] packetCount=1
[junit4] 2> 328816 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes took 0 msec
[junit4] 2> 328816 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=12 packetCount=1
[junit4] 2> 328817 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 328817 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 finishFullFlush success=true
[junit4] 2> 328818 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: findMerges: 1 segments
[junit4] 2> 328819 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: seg=_1(4.5):C1000 size=0.023 MB [floored]
[junit4] 2> 328819 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 328820 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: now merge
[junit4] 2> 328821 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: index: _1(4.5):C1000
[junit4] 2> 328821 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: no more merges pending; now return
[junit4] 2> 328822 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: startCommit(): start
[junit4] 2> 328822 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: startCommit index=_1(4.5):C1000 changeCount=8
[junit4] 2> 328823 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: done all syncs: [_1.fdx, _1_Lucene41_0.pos, _1.nvm, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 328824 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: pendingCommit != null
[junit4] 2> 328824 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: wrote segments file "segments_3"
[junit4] 2> 328825 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: now checkpoint "_1(4.5):C1000" [1 segments ; isCommit = true]
[junit4] 2> 328825 T258 C27 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_3,generation=3}
[junit4] 2> 328826 T258 C27 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 328826 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 328828 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.fnm"
[junit4] 2> 328828 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.doc"
[junit4] 2> 328829 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 328830 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.pos"
[junit4] 2> 328831 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 328832 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.nvd"
[junit4] 2> 328832 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 328833 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "segments_2"
[junit4] 2> 328833 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.fdx"
[junit4] 2> 328834 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.si"
[junit4] 2> 328835 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.nvm"
[junit4] 2> 328836 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.tim"
[junit4] 2> 328837 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 328837 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.fdt"
[junit4] 2> 328838 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 328838 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.tip"
[junit4] 2> 328839 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: 13 msec to checkpoint
[junit4] 2> 328839 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: done
[junit4] 2> 328840 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328840 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 328841 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: flush at getReader
[junit4] 2> 328841 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 startFullFlush
[junit4] 2> 328842 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328842 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: apply all deletes during flush
[junit4] 2> 328843 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes: no deletes; skipping
[junit4] 2> 328843 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=12 packetCount=0
[junit4] 2> 328845 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1000)
[junit4] 2> 328846 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 finishFullFlush success=true
[junit4] 2> 328847 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: getReader took 6 msec
[junit4] 2> 328847 T258 C27 oass.SolrIndexSearcher.<init> Opening Searcher@64ca7835 main
[junit4] 2> 328848 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 328849 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.doc"
[junit4] 2> 328849 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 328850 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 328850 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.pos"
[junit4] 2> 328851 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 328851 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _0.nvd
[junit4] 2> 328852 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.nvd"
[junit4] 2> 328852 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 328853 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 328853 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0_Lucene41_0.tim"
[junit4] 2> 328854 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 328854 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _0.fdt
[junit4] 2> 328855 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_0.fdt"
[junit4] 2> 328855 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 328856 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@64ca7835 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1000)}
[junit4] 2> 328857 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 328859 T262 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64ca7835 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1000)}
[junit4] 2> 328860 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 328861 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 328862 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 328862 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_0_Lucene41_0.pos"
[junit4] 2> 328863 T258 C27 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 328864 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _0.nvd
[junit4] 2> 328864 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_0.nvd"
[junit4] 2> 328865 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 328865 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 328865 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _0.fdt
[junit4] 2> 328866 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_0.fdt"
[junit4] 2> 328866 T258 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 87
[junit4] 2> 328942 T256 C27 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=1000 status=0 QTime=1
[junit4] 2> 328967 T251 oas.SolrTestCaseJ4.tearDown ###Ending testWithBinaryBean
[junit4] 2> 328981 T251 oas.SolrTestCaseJ4.setUp ###Starting testWithBinary
[junit4] 2> 328992 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328993 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 328994 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328994 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: flush at getReader
[junit4] 2> 328995 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255 startFullFlush
[junit4] 2> 328995 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 328996 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255: flush naked frozen global deletes
[junit4] 2> 328996 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: push deletes 1 deleted queries bytesUsed=32 delGen=14 packetCount=1 totBytesUsed=32
[junit4] 2> 328997 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 328997 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: apply all deletes during flush
[junit4] 2> 328998 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: applyDeletes: infos=[_1(4.5):C1000] packetCount=1
[junit4] 2> 329018 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: seg=_1(4.5):C1000 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1000 100% deleted
[junit4] 2> 329019 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: applyDeletes took 21 msec
[junit4] 2> 329021 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: now checkpoint "_1(4.5):C1000/1000" [1 segments ; isCommit = false]
[junit4] 2> 329021 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: 0 msec to checkpoint
[junit4] 2> 329022 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: drop 100% deleted segments: _1(4.5):C1000/1000
[junit4] 2> 329022 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 329023 T255 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-255]: 0 msec to checkpoint
[junit4] 2> 329023 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=9223372036854775807 packetCount=1
[junit4] 2> 329025 T255 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-255]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 329025 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
[junit4] 2> 329026 T255 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-255]: qtp294255203-255 finishFullFlush success=true
[junit4] 2> 329026 T255 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-255]: getReader took 32 msec
[junit4] 2> 329027 T255 C27 oass.SolrIndexSearcher.<init> Opening Searcher@6be3511c realtime
[junit4] 2> 329027 T255 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1444835637841625088)} 0 36
[junit4] 2> 329473 T260 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1 (1444835637906636800), 2 (1444835637908733952), 3 (1444835637908733953), 4 (1444835637908733954), 5 (1444835637909782528), 6 (1444835637909782529), 7 (1444835637910831104), 8 (1444835637911879680), 9 (1444835637911879681), 10 (1444835637911879682), ... (1000 adds)]} 0 421
[junit4] 2> 329481 T258 C27 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 329482 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: start
[junit4] 2> 329482 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: enter lock
[junit4] 2> 329483 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: now prepare
[junit4] 2> 329483 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: prepareCommit: flush
[junit4] 2> 329483 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: index before flush
[junit4] 2> 329484 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 startFullFlush
[junit4] 2> 329484 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=1000 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 329485 T258 C27 oasu.LoggingInfoStream.message [DWFC][qtp294255203-258]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 999 deleted terms (unique count=999) bytesUsed=166728, segment=_2, aborting=false, numDocsInRAM=1000, deleteQueue=DWDQ: [ generation: 8 ]]
[junit4] 2> 329491 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flush postings as segment _2 numDocs=1000
[junit4] 2> 329507 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: new segment has 0 deleted docs
[junit4] 2> 329508 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 329508 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushedFiles=[_2_Lucene41_0.pos, _2.nvm, _2_Lucene41_0.tim, _2.nvd, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 329509 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushed codec=Lucene45
[junit4] 2> 329520 T258 C27 oasu.LoggingInfoStream.message [DWPT][qtp294255203-258]: flushed: segment=_2 ramUsed=0.286 MB newFlushedSize(includes docstores)=0.024 MB docs/MB=42,269.359
[junit4] 2> 329521 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 329521 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: publishFlushedSegment
[junit4] 2> 329522 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: push deletes 1000 deleted terms (unique count=1000) bytesUsed=3072 delGen=16 packetCount=1 totBytesUsed=3072
[junit4] 2> 329522 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: publish sets newSegment delGen=17 seg=_2(4.5):C1000
[junit4] 2> 329523 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: now checkpoint "_2(4.5):C1000" [1 segments ; isCommit = false]
[junit4] 2> 329523 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: 0 msec to checkpoint
[junit4] 2> 329524 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: apply all deletes during flush
[junit4] 2> 329524 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes: infos=[_2(4.5):C1000] packetCount=1
[junit4] 2> 329525 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes took 1 msec
[junit4] 2> 329525 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=18 packetCount=1
[junit4] 2> 329526 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 329526 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 finishFullFlush success=true
[junit4] 2> 329527 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: findMerges: 1 segments
[junit4] 2> 329527 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: seg=_2(4.5):C1000 size=0.023 MB [floored]
[junit4] 2> 329528 T258 C27 oasu.LoggingInfoStream.message [TMP][qtp294255203-258]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 329528 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: now merge
[junit4] 2> 329529 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: index: _2(4.5):C1000
[junit4] 2> 329529 T258 C27 oasu.LoggingInfoStream.message [CMS][qtp294255203-258]: no more merges pending; now return
[junit4] 2> 329530 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: startCommit(): start
[junit4] 2> 329530 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: startCommit index=_2(4.5):C1000 changeCount=13
[junit4] 2> 329531 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: done all syncs: [_2.si, _2_Lucene41_0.pos, _2_Lucene41_0.tim, _2.nvm, _2.nvd, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 329532 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: pendingCommit != null
[junit4] 2> 329532 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: wrote segments file "segments_4"
[junit4] 2> 329532 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: now checkpoint "_2(4.5):C1000" [1 segments ; isCommit = true]
[junit4] 2> 329533 T258 C27 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58959802 lockFactory=org.apache.lucene.store.NativeFSLockFactory@454c8132),segFN=segments_4,generation=4}
[junit4] 2> 329534 T258 C27 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 329534 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 329535 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.fdx"
[junit4] 2> 329535 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.pos"
[junit4] 2> 329535 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 329536 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.nvm"
[junit4] 2> 329536 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.doc"
[junit4] 2> 329537 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 329537 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.fdt"
[junit4] 2> 329538 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 329538 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.si"
[junit4] 2> 329539 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.tim"
[junit4] 2> 329539 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 329540 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.nvd"
[junit4] 2> 329540 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 329541 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.tip"
[junit4] 2> 329541 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.fnm"
[junit4] 2> 329542 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "segments_3"
[junit4] 2> 329542 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: 9 msec to checkpoint
[junit4] 2> 329543 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: commit: done
[junit4] 2> 329543 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 329544 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 329544 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: flush at getReader
[junit4] 2> 329545 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 startFullFlush
[junit4] 2> 329546 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 329547 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: apply all deletes during flush
[junit4] 2> 329548 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: applyDeletes: no deletes; skipping
[junit4] 2> 329548 T258 C27 oasu.LoggingInfoStream.message [BD][qtp294255203-258]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=18 packetCount=0
[junit4] 2> 329567 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: return reader version=11 reader=StandardDirectoryReader(segments_4:11:nrt _2(4.5):C1000)
[junit4] 2> 329568 T258 C27 oasu.LoggingInfoStream.message [DW][qtp294255203-258]: qtp294255203-258 finishFullFlush success=true
[junit4] 2> 329568 T258 C27 oasu.LoggingInfoStream.message [IW][qtp294255203-258]: getReader took 24 msec
[junit4] 2> 329570 T258 C27 oass.SolrIndexSearcher.<init> Opening Searcher@1d25f490 main
[junit4] 2> 329572 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 329573 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.pos"
[junit4] 2> 329573 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 329574 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 329574 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.doc"
[junit4] 2> 329575 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 329575 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _1.fdt
[junit4] 2> 329577 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.fdt"
[junit4] 2> 329577 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 329578 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 329578 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1_Lucene41_0.tim"
[junit4] 2> 329579 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 329579 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete pending file _1.nvd
[junit4] 2> 329580 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: delete "_1.nvd"
[junit4] 2> 329580 T258 C27 oasu.LoggingInfoStream.message [IFD][qtp294255203-258]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 329581 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1d25f490 main{StandardDirectoryReader(segments_4:11:nrt _2(4.5):C1000)}
[junit4] 2> 329582 T262 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 329582 T258 C27 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 329584 T262 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d25f490 main{StandardDirectoryReader(segments_4:11:nrt _2(4.5):C1000)}
[junit4] 2> 329594 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 329594 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_1_Lucene41_0.pos"
[junit4] 2> 329598 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 329598 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 329605 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _1.fdt
[junit4] 2> 329606 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_1.fdt"
[junit4] 2> 329606 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 329607 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 329607 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete pending file _1.nvd
[junit4] 2> 329607 T262 oasu.LoggingInfoStream.message [IFD][searcherExecutor-151-thread-1]: delete "_1.nvd"
[junit4] 2> 329608 T258 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 127
[junit4] 2> 329618 T259 C27 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=1000 status=0 QTime=2
[junit4] 2> 329625 T251 oas.SolrTestCaseJ4.tearDown ###Ending testWithBinary
[junit4] 2> 329640 T251 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1090018507
[junit4] 2> 329641 T251 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@14c03d92
[junit4] 2> 329675 T251 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommit maxTime=15000ms,autocommits=1,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=3000,cumulative_deletesById=0,cumulative_deletesByQuery=3,cumulative_errors=0}
[junit4] 2> 329676 T251 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 329677 T251 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 329677 T251 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 329678 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: now flush at close waitForMerges=true
[junit4] 2> 329679 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 329680 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: index before flush _2(4.5):C1000
[junit4] 2> 329680 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker startFullFlush
[junit4] 2> 329681 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 329681 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker finishFullFlush success=true
[junit4] 2> 329682 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: apply all deletes during flush
[junit4] 2> 329683 T251 C27 oasu.LoggingInfoStream.message [BD][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 329683 T251 C27 oasu.LoggingInfoStream.message [BD][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=18 packetCount=0
[junit4] 2> 329684 T251 C27 oasu.LoggingInfoStream.message [CMS][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: now merge
[junit4] 2> 329684 T251 C27 oasu.LoggingInfoStream.message [CMS][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: index: _2(4.5):C1000
[junit4] 2> 329684 T251 C27 oasu.LoggingInfoStream.message [CMS][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: no more merges pending; now return
[junit4] 2> 329685 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: waitForMerges
[junit4] 2> 329685 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: waitForMerges done
[junit4] 2> 329686 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: now call final commit()
[junit4] 2> 329686 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: commit: start
[junit4] 2> 329687 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: commit: enter lock
[junit4] 2> 329687 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: commit: now prepare
[junit4] 2> 329688 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: prepareCommit: flush
[junit4] 2> 329688 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: index before flush _2(4.5):C1000
[junit4] 2> 329689 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker startFullFlush
[junit4] 2> 329690 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 329694 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: apply all deletes during flush
[junit4] 2> 329698 T251 C27 oasu.LoggingInfoStream.message [BD][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 329698 T251 C27 oasu.LoggingInfoStream.message [BD][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@447be9e9 minGen=18 packetCount=0
[junit4] 2> 329699 T251 C27 oasu.LoggingInfoStream.message [DW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker finishFullFlush success=true
[junit4] 2> 329699 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: startCommit(): start
[junit4] 2> 329700 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: skip startCommit(): no changes pending
[junit4] 2> 329700 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 329701 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: commit: done
[junit4] 2> 329701 T251 C27 oasu.LoggingInfoStream.message [IW][SUITE-TestBatchUpdate-seed#[214AB201C1076AE1]-worker]: at close: _2(4.5):C1000
[junit4] 2> 329704 T251 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 329705 T251 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 329706 T251 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index;done=false>>]
[junit4] 2> 329706 T251 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336/index
[junit4] 2> 329707 T251 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336;done=false>>]
[junit4] 2> 329708 T251 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-TestBatchUpdate-1377902431336
[junit4] 2> 329709 T251 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 329762 T251 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene45: {}, docValues:{}, sim=DefaultSimilarity, locale=es_PA, timezone=Europe/Dublin
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=108702256,total=216858624
[junit4] 2> NOTE: All tests run in this JVM: [CloudSolrServerTest, AnlysisResponseBaseTest, ContentStreamTest, TestSpellCheckResponse, SolrExampleEmbeddedTest, FieldAnalysisResponseTest, MultiCoreExampleJettyTest, TestHash, JettyWebappTest, SolrPingTest, MergeIndexesEmbeddedTest, ModifiableSolrParamsTest, QueryResponseTest, ClientUtilsTest, TestNamedListCodec, LargeVolumeEmbeddedTest, FacetFieldTest, TestBatchUpdate]
[junit4] Completed in 208.78s, 3 tests, 1 error <<< FAILURES!
[...truncated 87 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:402: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:382: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:202: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:455: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error
Total time: 104 minutes 52 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure