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/20 13:40:47 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b102) - Build #
7007 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/7007/
Java: 64bit/jdk1.8.0-ea-b102 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest.testUnicode
Error Message:
IOException occured when talking to server at: https://127.0.0.1:44314/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:44314/solr/collection1
at __randomizedtesting.SeedInfo.seed([9D0B6B8F743E2A0F:84C7DF85D684FBF8]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:436)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:68)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:54)
at org.apache.solr.client.solrj.SolrExampleTests.testUnicode(SolrExampleTests.java:375)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 45 more
Build Log:
[...truncated 10920 lines...]
[junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleJettyTest
[junit4] 2> 79064 T270 oas.SolrTestCaseJ4.startTrackingSearchers WARN startTrackingSearchers: numOpens=21 numCloses=21
[junit4] 2> 79064 T270 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 79065 T270 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/./solrtest-SolrExampleJettyTest-1376998629577
[junit4] 2> 79065 T270 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 79066 T270 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 79069 T270 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 79088 T270 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:44314
[junit4] 2> 79090 T270 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 79090 T270 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 79091 T270 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr
[junit4] 2> 79091 T270 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/'
[junit4] 2> 79107 T270 oasc.ConfigSolr.fromFile Loading container configuration from /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/solr.xml
[junit4] 2> 79120 T270 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 79121 T270 oasc.CoreContainer.<init> New CoreContainer 1940955063
[junit4] 2> 79121 T270 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/]
[junit4] 2> 79123 T270 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 79123 T270 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 79123 T270 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 79123 T270 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 79124 T270 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 79124 T270 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 79124 T270 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 79124 T270 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 79125 T270 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 79125 T270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 79128 T270 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr
[junit4] 2> 79131 T270 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/
[junit4] 2> 79132 T270 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 79132 T280 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1
[junit4] 2> 79133 T280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/'
[junit4] 2> 79154 T280 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 79155 T280 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 79155 T280 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 79155 T280 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 79155 T280 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 79156 T280 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 79156 T280 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 79156 T280 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 79156 T280 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 79171 T280 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 79175 T280 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 79199 T280 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 79200 T280 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 79206 T280 oass.IndexSchema.readSchema [null] Schema name=example
[junit4] 2> 79399 T280 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 79407 T280 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 79410 T280 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 79422 T280 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 79422 T280 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/, dataDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/
[junit4] 2> 79422 T280 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2ee57cf
[junit4] 2> 79423 T280 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 79423 T280 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 79424 T280 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577
[junit4] 2> 79424 T280 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index/
[junit4] 2> 79424 T280 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index' doesn't exist. Creating new index...
[junit4] 2> 79424 T280 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@1d3e0312
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: 0 msec to checkpoint
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: init: create=true
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@7dd24a3
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 79425 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: index before flush
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 startFullFlush
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 finishFullFlush success=true
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: apply all deletes during flush
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-140-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@9de9bc1 minGen=9223372036854775807 packetCount=0
[junit4] 2> 79426 T280 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-140-thread-1]: now merge
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-140-thread-1]: index:
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-140-thread-1]: no more merges pending; now return
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: waitForMerges
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: waitForMerges done
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: now call final commit()
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: start
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: enter lock
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: now prepare
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: prepareCommit: flush
[junit4] 2> 79427 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: index before flush
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 startFullFlush
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: apply all deletes during flush
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-140-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@9de9bc1 minGen=9223372036854775807 packetCount=0
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 finishFullFlush success=true
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: startCommit(): start
[junit4] 2> 79428 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: startCommit index= changeCount=1
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: done all syncs: []
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: pendingCommit != null
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 79429 T280 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_1,generation=1}
[junit4] 2> 79429 T280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: 0 msec to checkpoint
[junit4] 2> 79429 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: commit: done
[junit4] 2> 79430 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: at close:
[junit4] 2> 79430 T280 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 79430 T280 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 79430 T280 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 79430 T280 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 79430 T280 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 79433 T280 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 79433 T280 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 79433 T280 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 79434 T280 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 79434 T280 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 79434 T280 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 79435 T280 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 79436 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 79436 T280 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 79436 T280 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 79436 T280 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 79436 T280 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 79437 T280 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 79438 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 79438 T280 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 79438 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 79438 T280 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 79439 T280 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 79440 T280 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 79441 T280 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 79443 T280 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 79443 T280 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 79443 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@1d3e0312
[junit4] 2> 79444 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: init: load commit "segments_1"
[junit4] 2> 79444 T280 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_1,generation=1}
[junit4] 2> 79444 T280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 79444 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 79444 T280 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-140-thread-1]: 0 msec to checkpoint
[junit4] 2> 79444 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: init: create=false
[junit4] 2> 79444 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene42
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@49bdab1e
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: flush at getReader
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 startFullFlush
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: apply all deletes during flush
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-140-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=9223372036854775807 packetCount=0
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 79445 T280 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-140-thread-1]: coreLoadExecutor-140-thread-1 finishFullFlush success=true
[junit4] 2> 79446 T280 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-140-thread-1]: getReader took 1 msec
[junit4] 2> 79446 T280 oass.SolrIndexSearcher.<init> Opening Searcher@452371e2 main
[junit4] 2> 79446 T280 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 79446 T280 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> 79446 T280 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 79447 T280 oashc.QueryElevationComponent.inform Loading QueryElevation from: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 79452 T280 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 79453 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@452371e2 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C205 name=collection1 org.apache.solr.core.SolrCore@381270d3
[junit4] 2> 79454 T281 C205 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> 79454 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79454 T281 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 79454 T281 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 79455 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@452371e2 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 79456 T280 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 79456 T270 oass.SolrDispatchFilter.init user.dir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1
[junit4] 2> 79457 T270 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 79457 T270 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#44314
[junit4] 2> 79462 T270 oas.SolrTestCaseJ4.setUp ###Starting testSetNullUpdateOrder
[junit4] 2> 79463 T270 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C206 name=collection1 org.apache.solr.core.SolrCore@381270d3
[junit4] 2> 79535 T276 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdateOrder (1443887715498065920)]} 0 2
[junit4] 2> 79539 T278 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79539 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: start
[junit4] 2> 79539 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: enter lock
[junit4] 2> 79540 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: now prepare
[junit4] 2> 79540 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: prepareCommit: flush
[junit4] 2> 79540 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: index before flush
[junit4] 2> 79540 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 startFullFlush
[junit4] 2> 79540 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79541 T278 C206 oasu.LoggingInfoStream.message [DWFC][qtp682416384-278]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 1 ]]
[junit4] 2> 79541 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: flush postings as segment _0 numDocs=1
[junit4] 2> 79542 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: new segment has 0 deleted docs
[junit4] 2> 79542 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 79542 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4] 2> 79542 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: flushed codec=Lucene42
[junit4] 2> 79543 T278 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-278]: flushed: segment=_0 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,144.734
[junit4] 2> 79543 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 79543 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: publishFlushedSegment
[junit4] 2> 79543 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=2 packetCount=1 totBytesUsed=1024
[junit4] 2> 79544 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: publish sets newSegment delGen=3 seg=_0(4.5):C1
[junit4] 2> 79544 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 79544 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: 0 msec to checkpoint
[junit4] 2> 79544 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: apply all deletes during flush
[junit4] 2> 79544 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
[junit4] 2> 79545 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: applyDeletes took 1 msec
[junit4] 2> 79545 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=4 packetCount=1
[junit4] 2> 79545 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 79545 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 finishFullFlush success=true
[junit4] 2> 79545 T278 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-278]: findMerges: 1 segments
[junit4] 2> 79546 T278 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-278]: seg=_0(4.5):C1 size=0.001 MB [floored]
[junit4] 2> 79546 T278 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-278]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 79546 T278 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-278]: now merge
[junit4] 2> 79546 T278 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-278]: index: _0(4.5):C1
[junit4] 2> 79546 T278 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-278]: no more merges pending; now return
[junit4] 2> 79547 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: startCommit(): start
[junit4] 2> 79547 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: startCommit index=_0(4.5):C1 changeCount=3
[junit4] 2> 79547 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0.si, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4] 2> 79547 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: pendingCommit != null
[junit4] 2> 79548 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: wrote segments file "segments_2"
[junit4] 2> 79548 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 79548 T278 C206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_2,generation=2}
[junit4] 2> 79548 T278 C206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 79549 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 79549 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: delete "segments_1"
[junit4] 2> 79549 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: 1 msec to checkpoint
[junit4] 2> 79550 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: commit: done
[junit4] 2> 79550 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79550 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 79551 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: flush at getReader
[junit4] 2> 79551 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 startFullFlush
[junit4] 2> 79551 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79551 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: apply all deletes during flush
[junit4] 2> 79551 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: applyDeletes: no deletes; skipping
[junit4] 2> 79552 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=4 packetCount=0
[junit4] 2> 79553 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)
[junit4] 2> 79553 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 finishFullFlush success=true
[junit4] 2> 79553 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: getReader took 2 msec
[junit4] 2> 79553 T278 C206 oass.SolrIndexSearcher.<init> Opening Searcher@1418180 main
[junit4] 2> 79554 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1418180 main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 79554 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79554 T278 C206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 79555 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1418180 main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 79555 T278 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4] 2> 79559 T279 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[testSetNullUpdateOrder (1443887715524280320)]} 0 1
[junit4] 2> 79562 T277 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79562 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: start
[junit4] 2> 79563 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: enter lock
[junit4] 2> 79563 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: now prepare
[junit4] 2> 79563 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: prepareCommit: flush
[junit4] 2> 79563 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: index before flush _0(4.5):C1
[junit4] 2> 79564 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 startFullFlush
[junit4] 2> 79564 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79564 T277 C206 oasu.LoggingInfoStream.message [DWFC][qtp682416384-277]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 3 ]]
[junit4] 2> 79564 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: flush postings as segment _1 numDocs=1
[junit4] 2> 79565 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: new segment has 0 deleted docs
[junit4] 2> 79565 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 79565 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: flushedFiles=[_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 79566 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: flushed codec=Lucene42
[junit4] 2> 79566 T277 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-277]: flushed: segment=_1 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,376.084
[junit4] 2> 79566 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 79566 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: publishFlushedSegment
[junit4] 2> 79566 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=6 packetCount=1 totBytesUsed=1024
[junit4] 2> 79567 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: publish sets newSegment delGen=7 seg=_1(4.5):C1
[junit4] 2> 79567 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "_0(4.5):C1 _1(4.5):C1" [2 segments ; isCommit = false]
[junit4] 2> 79567 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 0 msec to checkpoint
[junit4] 2> 79567 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: apply all deletes during flush
[junit4] 2> 79567 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: applyDeletes: infos=[_0(4.5):C1, _1(4.5):C1] packetCount=1
[junit4] 2> 79568 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: seg=_0(4.5):C1 segGen=4 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=1 100% deleted
[junit4] 2> 79568 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: applyDeletes took 1 msec
[junit4] 2> 79568 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "_0(4.5):C1/1 _1(4.5):C1" [2 segments ; isCommit = false]
[junit4] 2> 79568 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 0 msec to checkpoint
[junit4] 2> 79568 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: drop 100% deleted segments: _0(4.5):C1/1
[junit4] 2> 79569 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "_1(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 79569 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 0 msec to checkpoint
[junit4] 2> 79569 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=8 packetCount=1
[junit4] 2> 79569 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 79569 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 finishFullFlush success=true
[junit4] 2> 79570 T277 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-277]: findMerges: 1 segments
[junit4] 2> 79570 T277 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-277]: seg=_1(4.5):C1 size=0.001 MB [floored]
[junit4] 2> 79570 T277 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-277]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 79570 T277 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-277]: now merge
[junit4] 2> 79571 T277 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-277]: index: _1(4.5):C1
[junit4] 2> 79571 T277 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-277]: no more merges pending; now return
[junit4] 2> 79571 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: startCommit(): start
[junit4] 2> 79571 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: startCommit index=_1(4.5):C1 changeCount=8
[junit4] 2> 79571 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: done all syncs: [_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 79572 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: pendingCommit != null
[junit4] 2> 79572 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: wrote segments file "segments_3"
[junit4] 2> 79572 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "_1(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 79572 T277 C206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_3,generation=3}
[junit4] 2> 79572 T277 C206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 79573 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 79573 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0.fnm"
[junit4] 2> 79573 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0_Lucene41_0.doc"
[junit4] 2> 79573 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 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> 79573 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "segments_2"
[junit4] 2> 79574 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0.fdx"
[junit4] 2> 79574 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0.si"
[junit4] 2> 79574 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0_Lucene41_0.tim"
[junit4] 2> 79574 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 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> 79574 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0.fdt"
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: delete "_0_Lucene41_0.tip"
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 2 msec to checkpoint
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: commit: done
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79575 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 79576 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: flush at getReader
[junit4] 2> 79576 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 startFullFlush
[junit4] 2> 79576 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79576 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: apply all deletes during flush
[junit4] 2> 79576 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: applyDeletes: no deletes; skipping
[junit4] 2> 79577 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=8 packetCount=0
[junit4] 2> 79577 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)
[junit4] 2> 79577 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 finishFullFlush success=true
[junit4] 2> 79578 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: getReader took 2 msec
[junit4] 2> 79578 T277 C206 oass.SolrIndexSearcher.<init> Opening Searcher@70746f94 main
[junit4] 2> 79578 T277 C206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 79578 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@70746f94 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)}
[junit4] 2> 79578 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79579 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70746f94 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)}
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _0.fdt
[junit4] 2> 79580 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_0.fdt"
[junit4] 2> 79580 T277 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 18
[junit4] 2> 79583 T276 C206 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:testSetNullUpdateOrder&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4] 2> 79584 T270 oas.SolrTestCaseJ4.tearDown ###Ending testSetNullUpdateOrder
[junit4] 2> 79589 T270 oas.SolrTestCaseJ4.setUp ###Starting testStreamingRequest
[junit4] 2> 79591 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79591 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 79592 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79592 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: flush at getReader
[junit4] 2> 79592 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 startFullFlush
[junit4] 2> 79592 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79592 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278: flush naked frozen global deletes
[junit4] 2> 79593 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: push deletes 1 deleted queries bytesUsed=36 delGen=10 packetCount=1 totBytesUsed=36
[junit4] 2> 79593 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 79593 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: apply all deletes during flush
[junit4] 2> 79593 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: applyDeletes: infos=[_1(4.5):C1] packetCount=1
[junit4] 2> 79594 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: seg=_1(4.5):C1 segGen=8 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
[junit4] 2> 79594 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: applyDeletes took 1 msec
[junit4] 2> 79594 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: now checkpoint "_1(4.5):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 79594 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: 0 msec to checkpoint
[junit4] 2> 79595 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: drop 100% deleted segments: _1(4.5):C1/1
[junit4] 2> 79595 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 79595 T278 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-278]: 0 msec to checkpoint
[junit4] 2> 79595 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=9223372036854775807 packetCount=1
[junit4] 2> 79595 T278 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-278]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 79596 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
[junit4] 2> 79596 T278 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-278]: qtp682416384-278 finishFullFlush success=true
[junit4] 2> 79596 T278 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-278]: getReader took 4 msec
[junit4] 2> 79596 T278 C206 oass.SolrIndexSearcher.<init> Opening Searcher@5a94d197 realtime
[junit4] 2> 79597 T278 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1443887715558883328)} 0 6
[junit4] 2> 79599 T279 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79599 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: start
[junit4] 2> 79599 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: enter lock
[junit4] 2> 79599 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: now prepare
[junit4] 2> 79599 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: prepareCommit: flush
[junit4] 2> 79600 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: index before flush
[junit4] 2> 79600 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: qtp682416384-279 startFullFlush
[junit4] 2> 79600 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79600 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: apply all deletes during flush
[junit4] 2> 79600 T279 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-279]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=9223372036854775807 packetCount=0
[junit4] 2> 79601 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: qtp682416384-279 finishFullFlush success=true
[junit4] 2> 79601 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: startCommit(): start
[junit4] 2> 79601 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: startCommit index= changeCount=11
[junit4] 2> 79601 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: done all syncs: []
[junit4] 2> 79601 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: pendingCommit != null
[junit4] 2> 79602 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: wrote segments file "segments_4"
[junit4] 2> 79602 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 79602 T279 C206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_4,generation=4}
[junit4] 2> 79602 T279 C206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1.fdx"
[junit4] 2> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1_Lucene41_0.doc"
[junit4] 2> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: 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> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1.fdt"
[junit4] 2> 79603 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 79604 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1.si"
[junit4] 2> 79604 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1_Lucene41_0.tim"
[junit4] 2> 79604 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: 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> 79604 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1_Lucene41_0.tip"
[junit4] 2> 79604 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "_1.fnm"
[junit4] 2> 79605 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: delete "segments_3"
[junit4] 2> 79605 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: 2 msec to checkpoint
[junit4] 2> 79605 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: done
[junit4] 2> 79605 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79605 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 79606 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79606 T279 C206 oass.SolrIndexSearcher.<init> Opening Searcher@37e5face main
[junit4] 2> 79606 T279 C206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 79606 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@37e5face main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 79606 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79607 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@37e5face main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _1.fdt
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_1.fdt"
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 79608 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 79608 T279 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4] 2> 79611 T277 C206 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1
[junit4] 2> 79615 T276 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79615 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: start
[junit4] 2> 79615 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: enter lock
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: now prepare
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: prepareCommit: flush
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: index before flush
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 startFullFlush
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79616 T276 C206 oasu.LoggingInfoStream.message [DWFC][qtp682416384-276]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=2061, segment=_2, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 7 ]]
[junit4] 2> 79617 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: flush postings as segment _2 numDocs=10
[junit4] 2> 79618 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: new segment has 0 deleted docs
[junit4] 2> 79618 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 79618 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: 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> 79618 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: flushed codec=Lucene42
[junit4] 2> 79618 T276 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-276]: flushed: segment=_2 ramUsed=0.073 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=8,616.072
[junit4] 2> 79619 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 79619 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: publishFlushedSegment
[junit4] 2> 79619 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=13 packetCount=1 totBytesUsed=1024
[junit4] 2> 79619 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: publish sets newSegment delGen=14 seg=_2(4.5):C10
[junit4] 2> 79620 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: now checkpoint "_2(4.5):C10" [1 segments ; isCommit = false]
[junit4] 2> 79620 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: 0 msec to checkpoint
[junit4] 2> 79620 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: apply all deletes during flush
[junit4] 2> 79620 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: applyDeletes: infos=[_2(4.5):C10] packetCount=1
[junit4] 2> 79620 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: applyDeletes took 0 msec
[junit4] 2> 79621 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=15 packetCount=1
[junit4] 2> 79621 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 79621 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 finishFullFlush success=true
[junit4] 2> 79621 T276 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-276]: findMerges: 1 segments
[junit4] 2> 79621 T276 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-276]: seg=_2(4.5):C10 size=0.001 MB [floored]
[junit4] 2> 79622 T276 C206 oasu.LoggingInfoStream.message [TMP][qtp682416384-276]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 79622 T276 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-276]: now merge
[junit4] 2> 79622 T276 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-276]: index: _2(4.5):C10
[junit4] 2> 79622 T276 C206 oasu.LoggingInfoStream.message [CMS][qtp682416384-276]: no more merges pending; now return
[junit4] 2> 79622 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: startCommit(): start
[junit4] 2> 79623 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: startCommit index=_2(4.5):C10 changeCount=14
[junit4] 2> 79623 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: 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> 79623 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: pendingCommit != null
[junit4] 2> 79623 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: wrote segments file "segments_5"
[junit4] 2> 79623 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: now checkpoint "_2(4.5):C10" [1 segments ; isCommit = true]
[junit4] 2> 79624 T276 C206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_5,generation=5}
[junit4] 2> 79624 T276 C206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 79624 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 79624 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "segments_4"
[junit4] 2> 79624 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: 1 msec to checkpoint
[junit4] 2> 79625 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: done
[junit4] 2> 79625 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79625 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 79625 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: flush at getReader
[junit4] 2> 79625 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 startFullFlush
[junit4] 2> 79626 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79626 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: apply all deletes during flush
[junit4] 2> 79626 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: applyDeletes: no deletes; skipping
[junit4] 2> 79626 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=15 packetCount=0
[junit4] 2> 79627 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: return reader version=11 reader=StandardDirectoryReader(segments_5:11:nrt _2(4.5):C10)
[junit4] 2> 79627 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 finishFullFlush success=true
[junit4] 2> 79627 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: getReader took 2 msec
[junit4] 2> 79627 T276 C206 oass.SolrIndexSearcher.<init> Opening Searcher@2c0a9 main
[junit4] 2> 79628 T276 C206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 79628 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@2c0a9 main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C10)}
[junit4] 2> 79628 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79629 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c0a9 main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C10)}
[junit4] 2> 79630 T276 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {add=[0 (1443887715581952000), 1 (1443887715583000576), 2 (1443887715583000577), 3 (1443887715583000578), 4 (1443887715583000579), 5 (1443887715583000580), 6 (1443887715584049152), 7 (1443887715584049153), 8 (1443887715584049154), 9 (1443887715584049155)],commit=} 0 17
[junit4] 2> 79633 T278 C206 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=id,score,_docid_&q=*:*&wt=javabin&version=2} hits=10 status=0 QTime=1
[junit4] 2> 79635 T279 C206 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=id,score,_docid_&q=*:*&wt=javabin&version=2} hits=10 status=0 QTime=0
[junit4] 2> 79636 T270 oas.SolrTestCaseJ4.tearDown ###Ending testStreamingRequest
[junit4] 2> 79641 T270 oas.SolrTestCaseJ4.setUp ###Starting testContentStreamRequest
[junit4] 2> 79643 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79643 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 79643 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79644 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: flush at getReader
[junit4] 2> 79644 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 startFullFlush
[junit4] 2> 79644 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79644 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277: flush naked frozen global deletes
[junit4] 2> 79644 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: push deletes 1 deleted queries bytesUsed=36 delGen=17 packetCount=1 totBytesUsed=36
[junit4] 2> 79645 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 79645 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: apply all deletes during flush
[junit4] 2> 79645 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: applyDeletes: infos=[_2(4.5):C10] packetCount=1
[junit4] 2> 79645 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: seg=_2(4.5):C10 segGen=15 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=10 100% deleted
[junit4] 2> 79646 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: applyDeletes took 1 msec
[junit4] 2> 79646 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "_2(4.5):C10/10" [1 segments ; isCommit = false]
[junit4] 2> 79646 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 0 msec to checkpoint
[junit4] 2> 79646 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: drop 100% deleted segments: _2(4.5):C10/10
[junit4] 2> 79647 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 79647 T277 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-277]: 0 msec to checkpoint
[junit4] 2> 79647 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=9223372036854775807 packetCount=1
[junit4] 2> 79647 T277 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-277]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 79647 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: return reader version=13 reader=StandardDirectoryReader(segments_5:13:nrt)
[junit4] 2> 79648 T277 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-277]: qtp682416384-277 finishFullFlush success=true
[junit4] 2> 79648 T277 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-277]: getReader took 4 msec
[junit4] 2> 79648 T277 C206 oass.SolrIndexSearcher.<init> Opening Searcher@4f127459 realtime
[junit4] 2> 79648 T277 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1443887715613409280)} 0 6
[junit4] 2> 79651 T276 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79651 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: start
[junit4] 2> 79651 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: enter lock
[junit4] 2> 79651 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: now prepare
[junit4] 2> 79651 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: prepareCommit: flush
[junit4] 2> 79651 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: index before flush
[junit4] 2> 79652 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 startFullFlush
[junit4] 2> 79652 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79652 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: apply all deletes during flush
[junit4] 2> 79652 T276 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-276]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=9223372036854775807 packetCount=0
[junit4] 2> 79652 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: qtp682416384-276 finishFullFlush success=true
[junit4] 2> 79653 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: startCommit(): start
[junit4] 2> 79653 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: startCommit index= changeCount=17
[junit4] 2> 79653 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: done all syncs: []
[junit4] 2> 79653 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: pendingCommit != null
[junit4] 2> 79654 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: wrote segments file "segments_6"
[junit4] 2> 79654 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 79655 T276 C206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_5,generation=5}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@763e1816 lockFactory=org.apache.lucene.store.NativeFSLockFactory@695cea2b),segFN=segments_6,generation=6}
[junit4] 2> 79655 T276 C206 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4] 2> 79656 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: deleteCommits: now decRef commit "segments_5"
[junit4] 2> 79656 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.si"
[junit4] 2> 79656 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2_Lucene41_0.pos"
[junit4] 2> 79656 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: unable to remove file "_2_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 79656 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2_Lucene41_0.tim"
[junit4] 2> 79657 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: unable to remove file "_2_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 79657 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.nvm"
[junit4] 2> 79657 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.nvd"
[junit4] 2> 79657 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: unable to remove file "_2.nvd": java.io.IOException: MockDirectoryWrapper: file "_2.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 79657 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.fdt"
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: unable to remove file "_2.fdt": java.io.IOException: MockDirectoryWrapper: file "_2.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2_Lucene41_0.doc"
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: unable to remove file "_2_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2_Lucene41_0.tip"
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "segments_5"
[junit4] 2> 79658 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.fdx"
[junit4] 2> 79659 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: delete "_2.fnm"
[junit4] 2> 79659 T276 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-276]: 4 msec to checkpoint
[junit4] 2> 79659 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: commit: done
[junit4] 2> 79659 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79659 T276 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-276]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 79660 T276 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-276]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79660 T276 C206 oass.SolrIndexSearcher.<init> Opening Searcher@46657229 main
[junit4] 2> 79660 T276 C206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 79660 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@46657229 main{StandardDirectoryReader(segments_5:13:nrt)}
[junit4] 2> 79661 T281 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 79662 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46657229 main{StandardDirectoryReader(segments_5:13:nrt)}
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _2_Lucene41_0.pos
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_2_Lucene41_0.pos"
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _2_Lucene41_0.tim
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_2_Lucene41_0.tim"
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _2.nvd
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_2.nvd"
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _2.fdt
[junit4] 2> 79662 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_2.fdt"
[junit4] 2> 79663 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete pending file _2_Lucene41_0.doc
[junit4] 2> 79663 T281 oasu.LoggingInfoStream.message [IFD][searcherExecutor-141-thread-1]: delete "_2_Lucene41_0.doc"
[junit4] 2> 79663 T276 C206 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 12
[junit4] 2> 79665 T278 C206 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 79673 T279 C206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 79673 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: start
[junit4] 2> 79673 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: enter lock
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: commit: now prepare
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: prepareCommit: flush
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: index before flush
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: qtp682416384-279 startFullFlush
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: anyChanges? numDocsInRam=10 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 79674 T279 C206 oasu.LoggingInfoStream.message [DWFC][qtp682416384-279]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 9 deleted terms (unique count=9) bytesUsed=2142, segment=_3, aborting=false, numDocsInRAM=10, deleteQueue=DWDQ: [ generation: 11 ]]
[junit4] 2> 79675 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: flush postings as segment _3 numDocs=10
[junit4] 2> 79677 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: new segment has 0 deleted docs
[junit4] 2> 79677 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 79677 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: flushedFiles=[_3.fdx, _3.nvd, _3_Lucene41_0.pos, _3_Lucene41_0.doc, _3_Lucene41_0.tip, _3.fnm, _3.nvm, _3_Lucene41_0.tim, _3.fdt]
[junit4] 2> 79677 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: flushed codec=Lucene42
[junit4] 2> 79678 T279 C206 oasu.LoggingInfoStream.message [DWPT][qtp682416384-279]: flushed: segment=_3 ramUsed=0.102 MB newFlushedSize(includes docstores)=0.004 MB docs/MB=2,309.13
[junit4] 2> 79678 T279 C206 oasu.LoggingInfoStream.message [DW][qtp682416384-279]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 79678 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: publishFlushedSegment
[junit4] 2> 79678 T279 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-279]: push deletes 10 deleted terms (unique count=10) bytesUsed=1024 delGen=20 packetCount=1 totBytesUsed=1024
[junit4] 2> 79679 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: publish sets newSegment delGen=21 seg=_3(4.5):C10
[junit4] 2> 79679 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: now checkpoint "_3(4.5):C10" [1 segments ; isCommit = false]
[junit4] 2> 79679 T279 C206 oasu.LoggingInfoStream.message [IFD][qtp682416384-279]: 0 msec to checkpoint
[junit4] 2> 79679 T279 C206 oasu.LoggingInfoStream.message [IW][qtp682416384-279]: apply all deletes during flush
[junit4] 2> 79679 T279 C206 oasu.LoggingInfoStream.message [BD][qtp682416384-279]: applyDeletes: infos=[_3(4.5):C10] packetCount=1
[junit4] 2> 79679 T279
[...truncated too long message...]
T276 C215 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=id,price_f,name,_version_&q=*:*&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4] 2> 285549 T270 oas.SolrTestCaseJ4.tearDown ###Ending testUpdateField
[junit4] 2> 285613 T270 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1940955063
[junit4] 2> 285613 T270 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@381270d3
[junit4] 2> 285627 T270 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=66,autocommit maxTime=15000ms,autocommits=1,soft autocommits=3,optimizes=2,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=1,cumulative_adds=221,cumulative_deletesById=5,cumulative_deletesByQuery=34,cumulative_errors=1}
[junit4] 2> 285628 T270 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 285628 T270 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 285628 T270 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 285629 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: now flush at close waitForMerges=true
[junit4] 2> 285629 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 285629 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: index before flush _1b(4.5):C1
[junit4] 2> 285630 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker startFullFlush
[junit4] 2> 285630 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 285630 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker finishFullFlush success=true
[junit4] 2> 285631 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: apply all deletes during flush
[junit4] 2> 285631 T270 C215 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 285631 T270 C215 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=276 packetCount=0
[junit4] 2> 285632 T270 C215 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: now merge
[junit4] 2> 285632 T270 C215 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: index: _1b(4.5):C1
[junit4] 2> 285632 T270 C215 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: no more merges pending; now return
[junit4] 2> 285632 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: waitForMerges
[junit4] 2> 285633 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: waitForMerges done
[junit4] 2> 285633 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: now call final commit()
[junit4] 2> 285633 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: commit: start
[junit4] 2> 285634 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: commit: enter lock
[junit4] 2> 285634 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: commit: now prepare
[junit4] 2> 285634 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: prepareCommit: flush
[junit4] 2> 285634 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: index before flush _1b(4.5):C1
[junit4] 2> 285635 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker startFullFlush
[junit4] 2> 285635 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 285635 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: apply all deletes during flush
[junit4] 2> 285636 T270 C215 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 285636 T270 C215 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@b7bc59e minGen=276 packetCount=0
[junit4] 2> 285636 T270 C215 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker finishFullFlush success=true
[junit4] 2> 285636 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: startCommit(): start
[junit4] 2> 285637 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: skip startCommit(): no changes pending
[junit4] 2> 285637 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 285637 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: commit: done
[junit4] 2> 285638 T270 C215 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleJettyTest-seed#[9D0B6B8F743E2A0F]-worker]: at close: _1b(4.5):C1
[junit4] 2> 285639 T270 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 285639 T270 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 285639 T270 oasc.CachingDirectoryFactory.closeCacheValue looking to close /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577 [CachedDir<<refCount=0;path=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577;done=false>>]
[junit4] 2> 285640 T270 oasc.CachingDirectoryFactory.close Closing directory: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577
[junit4] 2> 285640 T270 oasc.CachingDirectoryFactory.closeCacheValue looking to close /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index [CachedDir<<refCount=0;path=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index;done=false>>]
[junit4] 2> 285640 T270 oasc.CachingDirectoryFactory.close Closing directory: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-solrj/test/J1/solrtest-SolrExampleJettyTest-1376998629577/index
[junit4] 2> 285641 T270 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 285693 T270 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=es_MX, timezone=Australia/Darwin
[junit4] 2> NOTE: Linux 3.2.0-51-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=1,free=38995816,total=126418944
[junit4] 2> NOTE: All tests run in this JVM: [IteratorChainTest, TestSpellCheckResponse, TestSolrProperties, SolrExampleBinaryTest, SolrExampleStreamingTest, TestHash, MultiCoreEmbeddedTest, FieldAnalysisResponseTest, TestFastInputStream, BasicHttpSolrServerTest, TestNamedListCodec, TestLBHttpSolrServer, SolrExampleJettyTest]
[junit4] Completed on J1 in 206.67s, 27 tests, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:395: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:375: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:194: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:450: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1233: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error
Total time: 49 minutes 44 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b102 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_25) - Build # 7008
- Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/7008/
Java: 32bit/jdk1.7.0_25 -server -XX:+UseSerialGC
2 tests failed.
REGRESSION: org.apache.solr.cloud.ClusterStateUpdateTest.testCoreRegistration
Error Message:
Stack Trace:
org.apache.solr.common.cloud.ZooKeeperException:
at __randomizedtesting.SeedInfo.seed([81E253D7EDD52CF9:3F69357894AF22CC]:0)
at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:277)
at org.apache.solr.core.CoreContainer.registerCore(CoreContainer.java:452)
at org.apache.solr.core.CoreContainer.register(CoreContainer.java:471)
at org.apache.solr.cloud.ClusterStateUpdateTest.testCoreRegistration(ClusterStateUpdateTest.java:162)
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.solr.common.SolrException: Error getting leader from zk for shard shard1
at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:863)
at org.apache.solr.cloud.ZkController.register(ZkController.java:772)
at org.apache.solr.cloud.ZkController.register(ZkController.java:722)
at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:263)
... 43 more
Caused by: org.apache.solr.common.SolrException: No registered leader was found, collection:testcore slice:shard1
at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:487)
at org.apache.solr.common.cloud.ZkStateReader.getLeaderUrl(ZkStateReader.java:461)
at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:842)
... 46 more
REGRESSION: org.apache.solr.schema.TestCloudManagedSchemaAddField.testDistribSearch
Error Message:
Max retry count 20 exceeded after 285 ms. QUERY FAILED: xpath=/response/lst[@name='responseHeader']/int[@name='status'][.='0'] request=/schema/fields/newfield9?wt=xml response=<?xml version="1.0" encoding="UTF-8"?> <response> <lst name="responseHeader"> <int name="status">404</int> <int name="QTime">1</int> </lst> <lst name="error"> <str name="msg">Field 'newfield9' not found.</str> <int name="code">404</int> </lst> </response>
Stack Trace:
java.lang.AssertionError: Max retry count 20 exceeded after 285 ms. QUERY FAILED: xpath=/response/lst[@name='responseHeader']/int[@name='status'][.='0'] request=/schema/fields/newfield9?wt=xml response=<?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader">
<int name="status">404</int>
<int name="QTime">1</int>
</lst>
<lst name="error">
<str name="msg">Field 'newfield9' not found.</str>
<int name="code">404</int>
</lst>
</response>
at __randomizedtesting.SeedInfo.seed([81E253D7EDD52CF9:4DDCF9A8A4CC5]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.schema.TestCloudManagedSchemaAddField.doTest(TestCloudManagedSchemaAddField.java:127)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
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)
Build Log:
[...truncated 9686 lines...]
[junit4] Suite: org.apache.solr.schema.TestCloudManagedSchemaAddField
[junit4] 2> 278697 T648 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4] 2> 278700 T648 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-TestCloudManagedSchemaAddField-1377003550607
[junit4] 2> 278700 T648 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 278701 T649 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 278801 T648 oasc.ZkTestServer.run start zk server on port:38240
[junit4] 2> 278802 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 279152 T655 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c946f name:ZooKeeperConnection Watcher:127.0.0.1:38240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 279152 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 279152 T648 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 279272 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 279310 T657 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@92682d name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 279311 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 279312 T648 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 279400 T648 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 279428 T648 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 279456 T648 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 279483 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-managed-schema.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 279483 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 279550 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 279550 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 279629 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 279630 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 279710 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 279711 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 279745 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 279745 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 279772 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 279773 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 279866 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 279866 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 279900 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 279901 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 280008 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 280008 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 280039 T648 oasc.AbstractZkTestCase.putConfig put /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 280039 T648 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 280160 T648 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 280163 T648 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58965
[junit4] 2> 280163 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 280164 T648 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 280164 T648 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990
[junit4] 2> 280164 T648 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/'
[junit4] 2> 280173 T648 oasc.ConfigSolr.fromFile Loading container configuration from /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/solr.xml
[junit4] 2> 280215 T648 oasc.CoreContainer.<init> New CoreContainer 23682713
[junit4] 2> 280216 T648 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/]
[junit4] 2> 280217 T648 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 280217 T648 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 280218 T648 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 280218 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 280218 T648 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 280219 T648 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 280219 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 280219 T648 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 280220 T648 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 280220 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 280224 T648 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38240/solr
[junit4] 2> 280233 T648 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 280234 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 280272 T668 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3575ff name:ZooKeeperConnection Watcher:127.0.0.1:38240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 280272 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 280312 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 280317 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 280349 T670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@760ab8 name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 280350 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 280396 T648 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 280534 T648 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 280583 T648 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 280639 T648 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58965_
[junit4] 2> 280683 T648 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58965_
[junit4] 2> 280707 T648 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 280805 T648 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 280827 T648 oasc.Overseer.start Overseer (id=90243304692711427-127.0.0.1:58965_-n_0000000000) starting
[junit4] 2> 281209 T648 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 281295 T672 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 281295 T648 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 281335 T648 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 281372 T648 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 281380 T671 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 281384 T673 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 281384 T673 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 281416 T673 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 282886 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 282890 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard":null,
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:58965_",
[junit4] 2> "base_url":"http://127.0.0.1:58965"}
[junit4] 2> 282890 T671 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
[junit4] 2> 282896 T671 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 283005 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 283417 T673 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 283417 T673 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1
[junit4] 2> 283417 T673 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4] 2> 283418 T673 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 283418 T673 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 283420 T673 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/'
[junit4] 2> 283421 T673 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/lib/README' to classloader
[junit4] 2> 283421 T673 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/lib/classes/' to classloader
[junit4] 2> 283458 T673 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 283482 T673 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 283488 T673 oass.ManagedIndexSchemaFactory.create The schema is configured as managed, but managed schema resource managed-schema not found - loading non-managed schema schema.xml instead
[junit4] 2> 283491 T673 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 283497 T673 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 283808 T673 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 283809 T673 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 283809 T673 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 283815 T673 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 283817 T673 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 283832 T673 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 283834 T673 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 283837 T673 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 283839 T673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 283839 T673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 283839 T673 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 283840 T673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 283840 T673 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 284124 T673 oass.ManagedIndexSchema.persistManagedSchemaToZooKeeper Created and persisted managed schema znode at /configs/conf1/managed-schema
[junit4] 2> 284126 T673 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml.bak
[junit4] 2> 284289 T673 oass.ManagedIndexSchemaFactory.zkUgradeToManagedSchema After upgrading to managed schema in ZooKeeper, renamed the non-managed schema /configs/conf1/schema.xml to /configs/conf1/schema.xml.bak
[junit4] 2> 284290 T673 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4] 2> 284290 T673 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/, dataDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/
[junit4] 2> 284290 T673 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 284298 T673 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data
[junit4] 2> 284299 T673 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/index/
[junit4] 2> 284299 T673 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/index' doesn't exist. Creating new index...
[junit4] 2> 284299 T673 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/index
[junit4] 2> 284299 T673 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=14, maxMergeAtOnceExplicit=34, maxMergedSegmentMB=84.515625, floorSegmentMB=0.6884765625, forceMergeDeletesPctAllowed=28.49321646487287, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.38545737948172587
[junit4] 2> 284480 T673 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@16d46ba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 284481 T673 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 284482 T673 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 284482 T673 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 284482 T673 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 284482 T673 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 284483 T673 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 284483 T673 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 284483 T673 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 284485 T673 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 284487 T673 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 284487 T673 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 284488 T673 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=46, maxMergedSegmentMB=62.9248046875, floorSegmentMB=1.6123046875, forceMergeDeletesPctAllowed=21.67597592140337, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 284488 T673 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-controljetty-1377003551990/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@16d46ba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 284488 T673 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 284489 T673 oass.SolrIndexSearcher.<init> Opening Searcher@de838d main
[junit4] 2> 284490 T673 oass.ZkIndexSchemaReader.createSchemaWatcher Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema ...
[junit4] 2> 284493 T674 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@de838d main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 284493 T673 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 284493 T673 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58965 collection:control_collection shard:shard1
[junit4] 2> 284496 T673 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 284500 T673 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4] 2> 284917 T673 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 284995 T673 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 284995 T673 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 284996 T673 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58965/collection1/
[junit4] 2> 284997 T673 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 284997 T673 oasc.SyncStrategy.syncToMe http://127.0.0.1:58965/collection1/ has no replicas
[junit4] 2> 284997 T673 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58965/collection1/ shard1
[junit4] 2> 284997 T673 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4] 2> 286260 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 286606 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 286738 T673 oasc.ZkController.register We are http://127.0.0.1:58965/collection1/ and leader is http://127.0.0.1:58965/collection1/
[junit4] 2> 286738 T673 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58965
[junit4] 2> 286738 T673 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 286739 T673 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 286739 T673 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 286773 T673 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 286774 T648 oass.SolrDispatchFilter.init user.dir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 286774 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 286775 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 286778 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4] 2> 286781 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 286806 T677 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@988352 name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 286806 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 286808 T648 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 286812 T648 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4] 2> 286899 T648 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 286902 T648 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38005
[junit4] 2> 286902 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 286902 T648 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 286903 T648 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719
[junit4] 2> 286903 T648 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/'
[junit4] 2> 286912 T648 oasc.ConfigSolr.fromFile Loading container configuration from /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/solr.xml
[junit4] 2> 286950 T648 oasc.CoreContainer.<init> New CoreContainer 1570275
[junit4] 2> 286951 T648 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/]
[junit4] 2> 286952 T648 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 286952 T648 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 286952 T648 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 286953 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 286953 T648 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 286953 T648 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 286953 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 286954 T648 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 286954 T648 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 286954 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 286957 T648 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38240/solr
[junit4] 2> 286958 T648 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 286958 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 287006 T688 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f7bf39 name:ZooKeeperConnection Watcher:127.0.0.1:38240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 287006 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 287061 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 287065 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 287117 T690 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1132e2b name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 287117 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 287196 T648 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 288200 T648 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38005_
[junit4] 2> 288261 T648 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38005_
[junit4] 2> 288263 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 288318 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "numShards":"1",
[junit4] 2> "shard":"shard1",
[junit4] 2> "roles":null,
[junit4] 2> "state":"active",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"control_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:58965_",
[junit4] 2> "base_url":"http://127.0.0.1:58965"}
[junit4] 2> 288318 T677 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 288318 T690 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 288867 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 288868 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 288874 T691 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 288875 T691 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 288956 T691 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 288957 T670 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 288957 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 288960 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 290459 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 290460 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "numShards":"4",
[junit4] 2> "shard":null,
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:38005_",
[junit4] 2> "base_url":"http://127.0.0.1:38005"}
[junit4] 2> 290460 T671 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4]
[junit4] 2> 290460 T671 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 291039 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 291039 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 291039 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 291957 T691 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 291957 T691 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1
[junit4] 2> 291957 T691 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 291958 T691 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 291958 T691 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 291960 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/'
[junit4] 2> 291960 T691 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/lib/README' to classloader
[junit4] 2> 291960 T691 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/lib/classes/' to classloader
[junit4] 2> 291994 T691 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 292018 T691 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 292020 T691 oass.IndexSchema.readSchema Reading Solr Schema from managed-schema
[junit4] 2> 292025 T691 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 292346 T691 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 292346 T691 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 292347 T691 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 292351 T691 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 292352 T691 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 292356 T691 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 292360 T691 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 292370 T691 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 292371 T691 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 292371 T691 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 292371 T691 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 292372 T691 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 292372 T691 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 292375 T691 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4] 2> 292375 T691 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/, dataDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/
[junit4] 2> 292375 T691 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 292376 T691 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data
[junit4] 2> 292376 T691 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/index/
[junit4] 2> 292376 T691 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/index' doesn't exist. Creating new index...
[junit4] 2> 292376 T691 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/index
[junit4] 2> 292377 T691 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=14, maxMergeAtOnceExplicit=34, maxMergedSegmentMB=84.515625, floorSegmentMB=0.6884765625, forceMergeDeletesPctAllowed=28.49321646487287, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.38545737948172587
[junit4] 2> 292565 T691 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1e4c358; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 292565 T691 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 292566 T691 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 292566 T691 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 292567 T691 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 292567 T691 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 292567 T691 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 292567 T691 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 292567 T691 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 292569 T691 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 292571 T691 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 292571 T691 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 292572 T691 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=46, maxMergedSegmentMB=62.9248046875, floorSegmentMB=1.6123046875, forceMergeDeletesPctAllowed=21.67597592140337, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 292573 T691 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty1-1377003558719/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1e4c358; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 292573 T691 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 292573 T691 oass.SolrIndexSearcher.<init> Opening Searcher@1cb92d7 main
[junit4] 2> 292573 T691 oass.ZkIndexSchemaReader.createSchemaWatcher Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema ...
[junit4] 2> 292575 T692 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cb92d7 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 292575 T691 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 292576 T691 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38005 collection:collection1 shard:shard1
[junit4] 2> 292576 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 292579 T691 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 292689 T691 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 292734 T691 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 292734 T691 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 292734 T691 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38005/collection1/
[junit4] 2> 292735 T691 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 292735 T691 oasc.SyncStrategy.syncToMe http://127.0.0.1:38005/collection1/ has no replicas
[junit4] 2> 292735 T691 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38005/collection1/ shard1
[junit4] 2> 292735 T691 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 294066 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 294178 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 294178 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 294178 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 294213 T691 oasc.ZkController.register We are http://127.0.0.1:38005/collection1/ and leader is http://127.0.0.1:38005/collection1/
[junit4] 2> 294214 T691 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38005
[junit4] 2> 294214 T691 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 294214 T691 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 294214 T691 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 294245 T691 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 294247 T648 oass.SolrDispatchFilter.init user.dir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 294247 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 294247 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 294310 T648 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 294313 T648 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36768
[junit4] 2> 294313 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 294314 T648 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 294314 T648 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156
[junit4] 2> 294314 T648 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/'
[junit4] 2> 294323 T648 oasc.ConfigSolr.fromFile Loading container configuration from /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/solr.xml
[junit4] 2> 294359 T648 oasc.CoreContainer.<init> New CoreContainer 17276972
[junit4] 2> 294360 T648 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/]
[junit4] 2> 294361 T648 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 294361 T648 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 294361 T648 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 294361 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 294362 T648 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 294362 T648 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 294362 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 294362 T648 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 294363 T648 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 294363 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 294366 T648 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38240/solr
[junit4] 2> 294366 T648 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 294367 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 294400 T704 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78db10 name:ZooKeeperConnection Watcher:127.0.0.1:38240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 294400 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 294422 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 294425 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 294450 T706 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c333a name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 294450 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 294497 T648 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 295500 T648 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36768_
[junit4] 2> 295522 T648 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36768_
[junit4] 2> 295567 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 295567 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 295568 T670 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 295568 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 295569 T706 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 295570 T677 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 295571 T690 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 295615 T707 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 295615 T707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 295656 T707 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 295747 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 295748 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "numShards":"4",
[junit4] 2> "shard":"shard1",
[junit4] 2> "roles":null,
[junit4] 2> "state":"active",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:38005_",
[junit4] 2> "base_url":"http://127.0.0.1:38005"}
[junit4] 2> 295957 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "numShards":"4",
[junit4] 2> "shard":null,
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:36768_",
[junit4] 2> "base_url":"http://127.0.0.1:36768"}
[junit4] 2> 295957 T671 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=4
[junit4] 2> 295957 T671 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard4
[junit4] 2> 296022 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 296022 T706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 296023 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 296023 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 296656 T707 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 296656 T707 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1
[junit4] 2> 296656 T707 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 296657 T707 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 296657 T707 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 296659 T707 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/'
[junit4] 2> 296659 T707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/lib/README' to classloader
[junit4] 2> 296659 T707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/lib/classes/' to classloader
[junit4] 2> 296694 T707 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 296718 T707 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 296719 T707 oass.IndexSchema.readSchema Reading Solr Schema from managed-schema
[junit4] 2> 296725 T707 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 297037 T707 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 297037 T707 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 297038 T707 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 297048 T707 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 297050 T707 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 297053 T707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 297056 T707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 297065 T707 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 297066 T707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 297066 T707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 297067 T707 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 297068 T707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 297068 T707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 297070 T707 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4] 2> 297070 T707 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/, dataDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/
[junit4] 2> 297071 T707 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 297071 T707 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data
[junit4] 2> 297071 T707 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/index/
[junit4] 2> 297071 T707 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/index' doesn't exist. Creating new index...
[junit4] 2> 297072 T707 oasc.CachingDirectoryFactory.get return new directory for /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/index
[junit4] 2> 297072 T707 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=14, maxMergeAtOnceExplicit=34, maxMergedSegmentMB=84.515625, floorSegmentMB=0.6884765625, forceMergeDeletesPctAllowed=28.49321646487287, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.38545737948172587
[junit4] 2> 297421 T707 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@30907c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 297421 T707 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 297422 T707 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 297422 T707 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 297423 T707 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 297424 T707 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 297424 T707 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 297424 T707 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 297425 T707 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 297430 T707 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 297433 T707 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 297433 T707 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 297433 T707 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=46, maxMergedSegmentMB=62.9248046875, floorSegmentMB=1.6123046875, forceMergeDeletesPctAllowed=21.67597592140337, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 297434 T707 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty2-1377003566156/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@30907c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4] 2> 297434 T707 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 297435 T707 oass.SolrIndexSearcher.<init> Opening Searcher@1f7069a main
[junit4] 2> 297435 T707 oass.ZkIndexSchemaReader.createSchemaWatcher Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema ...
[junit4] 2> 297437 T708 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f7069a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 297437 T707 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 297437 T707 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36768 collection:collection1 shard:shard4
[junit4] 2> 297437 T707 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 297441 T707 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard4/election
[junit4] 2> 297600 T707 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard4
[junit4] 2> 297645 T707 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 297645 T707 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 297645 T707 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36768/collection1/
[junit4] 2> 297646 T707 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 297646 T707 oasc.SyncStrategy.syncToMe http://127.0.0.1:36768/collection1/ has no replicas
[junit4] 2> 297646 T707 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36768/collection1/ shard4
[junit4] 2> 297646 T707 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard4
[junit4] 2> 299125 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 299500 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 299500 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 299500 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 299500 T706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 299522 T707 oasc.ZkController.register We are http://127.0.0.1:36768/collection1/ and leader is http://127.0.0.1:36768/collection1/
[junit4] 2> 299522 T707 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36768
[junit4] 2> 299522 T707 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 299522 T707 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 299523 T707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 299589 T707 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 299590 T648 oass.SolrDispatchFilter.init user.dir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4] 2> 299591 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 299591 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 299656 T648 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 299659 T648 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50884
[junit4] 2> 299659 T648 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 299659 T648 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 299660 T648 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500
[junit4] 2> 299660 T648 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/'
[junit4] 2> 299669 T648 oasc.ConfigSolr.fromFile Loading container configuration from /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/solr.xml
[junit4] 2> 299710 T648 oasc.CoreContainer.<init> New CoreContainer 7645817
[junit4] 2> 299710 T648 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/]
[junit4] 2> 299711 T648 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 299711 T648 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 299711 T648 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 299712 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 299712 T648 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 299712 T648 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 299712 T648 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 299713 T648 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 299713 T648 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 299713 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 299716 T648 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38240/solr
[junit4] 2> 299716 T648 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 299717 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 299739 T720 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@506ea2 name:ZooKeeperConnection Watcher:127.0.0.1:38240 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 299739 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 299761 T648 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 299764 T648 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 299789 T722 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c5124d name:ZooKeeperConnection Watcher:127.0.0.1:38240/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 299789 T648 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 299835 T648 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 300839 T648 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50884_
[junit4] 2> 300894 T648 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50884_
[junit4] 2> 300917 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 300918 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4] 2> 300918 T670 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 300919 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 300919 T722 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 300919 T706 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 300919 T706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4] 2> 300920 T677 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 300920 T690 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 300949 T723 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 300949 T723 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 300972 T723 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 301114 T671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 301115 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "numShards":"4",
[junit4] 2> "shard":"shard4",
[junit4] 2> "roles":null,
[junit4] 2> "state":"active",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:36768_",
[junit4] 2> "base_url":"http://127.0.0.1:36768"}
[junit4] 2> 301162 T671 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=4 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "numShards":"4",
[junit4] 2> "shard":null,
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"collection1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:50884_",
[junit4] 2> "base_url":"http://127.0.0.1:50884"}
[junit4] 2> 301163 T671 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=4
[junit4] 2> 301163 T671 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 301378 T670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 301378 T690 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 301378 T677 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 301378 T706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 301378 T722 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 301973 T723 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 301973 T723 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/collection1
[junit4] 2> 301973 T723 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 301974 T723 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 301975 T723 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 301976 T723 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/collection1/'
[junit4] 2> 301977 T723 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/collection1/lib/README' to classloader
[junit4] 2> 301977 T723 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/collection1/lib/classes/' to classloader
[junit4] 2> 302004 T723 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 302034 T723 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 302036 T723 oass.IndexSchema.readSchema Reading Solr Schema from managed-schema
[junit4] 2> 302041 T723 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 302355 T723 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 302355 T723 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 302355 T723 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 302360 T723 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 302362 T723 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 302365 T723 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 302368 T723 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 302378 T723 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 302379 T723 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 302379 T723 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 302379 T723 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 302380 T723 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 302380 T723 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 302389 T723 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4] 2> 302389 T723 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.schema.TestCloudManagedSchemaAddField-jetty3-1377003571500/collection1/, dataDir=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/bui
[...truncated too long message...]
but Solr cannot talk to ZK
[junit4] 2> 2488732 T2934 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 2488777 T2934 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4] 2> 2488777 T2934 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4] 2> 2488777 T2934 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> 2488777 T2934 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:1663/solr/collection1/ shard1
[junit4] 2> 2488777 T2934 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 2488843 T2934 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 2488844 T2934 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 2489710 T2889 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 2489711 T2889 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 2489766 T2889 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@177620c
[junit4] 2> 2489775 T2889 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4] 2> 2489776 T2889 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 2489776 T2889 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 2489776 T2889 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 2489777 T2889 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 2489777 T2889 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 2489778 T2889 oasc.CachingDirectoryFactory.closeCacheValue looking to close /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3 [CachedDir<<refCount=0;path=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3;done=false>>]
[junit4] 2> 2489778 T2889 oasc.CachingDirectoryFactory.close Closing directory: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3
[junit4] 2> 2489778 T2889 oasc.CachingDirectoryFactory.closeCacheValue looking to close /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3/index [CachedDir<<refCount=0;path=/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3/index;done=false>>]
[junit4] 2> 2489778 T2889 oasc.CachingDirectoryFactory.close Closing directory: /var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ClusterStateUpdateTest-1377004506828/data3/index
[junit4] 2> 2489779 T2937 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90243367359610892-127.0.0.1:1663_solr-n_0000000006) am no longer a leader.
[junit4] 2> 2489800 T2889 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:60378 60378
[junit4] 2> 2490172 T2889 oas.SolrTestCaseJ4.tearDown ###Ending testCoreRegistration
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ClusterStateUpdateTest -Dtests.method=testCoreRegistration -Dtests.seed=81E253D7EDD52CF9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_HN -Dtests.timezone=Europe/Athens -Dtests.file.encoding=US-ASCII
[junit4] ERROR 1255s J0 | ClusterStateUpdateTest.testCoreRegistration <<<
[junit4] > Throwable #1: org.apache.solr.common.cloud.ZooKeeperException:
[junit4] > at __randomizedtesting.SeedInfo.seed([81E253D7EDD52CF9:3F69357894AF22CC]:0)
[junit4] > at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:277)
[junit4] > at org.apache.solr.core.CoreContainer.registerCore(CoreContainer.java:452)
[junit4] > at org.apache.solr.core.CoreContainer.register(CoreContainer.java:471)
[junit4] > at org.apache.solr.cloud.ClusterStateUpdateTest.testCoreRegistration(ClusterStateUpdateTest.java:162)
[junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4] > Caused by: org.apache.solr.common.SolrException: Error getting leader from zk for shard shard1
[junit4] > at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:863)
[junit4] > at org.apache.solr.cloud.ZkController.register(ZkController.java:772)
[junit4] > at org.apache.solr.cloud.ZkController.register(ZkController.java:722)
[junit4] > at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:263)
[junit4] > ... 43 more
[junit4] > Caused by: org.apache.solr.common.SolrException: No registered leader was found, collection:testcore slice:shard1
[junit4] > at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:487)
[junit4] > at org.apache.solr.common.cloud.ZkStateReader.getLeaderUrl(ZkStateReader.java:461)
[junit4] > at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:842)
[junit4] > ... 46 more
[junit4] 2> 2490181 T2889 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> 1255289 T2888 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> 2491099 T2934 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 2491099 T2934 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 2491100 T2934 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=es_HN, timezone=Europe/Athens
[junit4] 2> NOTE: Linux 3.2.0-51-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=1,free=105527576,total=227647488
[junit4] 2> NOTE: All tests run in this JVM: [SolrTestCaseJ4Test, TestPostingsSolrHighlighter, SimpleFacetsTest, CircularListTest, DocValuesTest, SliceStateTest, BlockDirectoryTest, TestJmxMonitoredMap, TestLRUCache, DOMUtilTest, AutoCommitTest, ShardRoutingTest, TestSystemIdResolver, TestWriterPerf, HdfsDirectoryTest, ZkControllerTest, TestShardHandlerFactory, TestManagedSchemaFieldResource, TestStressVersions, UpdateRequestProcessorFactoryTest, TestPerFieldSimilarity, DistributedQueryElevationComponentTest, SystemInfoHandlerTest, IndexSchemaTest, TermsComponentTest, TestLuceneMatchVersion, DocumentBuilderTest, MoreLikeThisHandlerTest, BasicFunctionalityTest, HdfsUnloadDistributedZkTest, UUIDFieldTest, FieldMutatingUpdateProcessorTest, TestCoreContainer, DateMathParserTest, TestSuggestSpellingConverter, AnalysisAfterCoreReloadTest, TestSearchPerf, SpatialFilterTest, TestRemoteStreaming, SyncSliceTest, StatelessScriptUpdateProcessorFactoryTest, SoftAutoCommitTest, SolrCoreTest, DirectUpdateHandlerOptimizeTest, TestQueryUtils, TestSolrQueryParserResource, TestExtendedDismaxParser, OverseerCollectionProcessorTest, ResourceLoaderTest, QueryParsingTest, TestDocumentBuilder, SolrInfoMBeanTest, TestImplicitCoreProperties, BadCopyFieldTest, ScriptEngineTest, TestFaceting, TestTrie, TestPHPSerializedResponseWriter, ParsingFieldUpdateProcessorsTest, TestJoin, RegexBoostProcessorTest, TestDocSet, TestMergePolicyConfig, TestConfig, EchoParamsTest, TestSolrXmlPersistence, TestReplicationHandler, TestReversedWildcardFilterFactory, ReturnFieldsTest, LegacyHTMLStripCharFilterTest, StressHdfsTest, SearchHandlerTest, SynonymTokenizerTest, LukeRequestHandlerTest, TestRandomMergePolicy, TestRandomDVFaceting, SchemaVersionSpecificBehaviorTest, BasicDistributedZkTest, UnloadDistributedZkTest, OverseerTest, BasicZkTest, ClusterStateUpdateTest]
[junit4] Completed on J0 in 1256.30s, 1 test, 1 error <<< FAILURES!
[...truncated 11 lines...]
BUILD FAILED
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:395: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:375: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:450: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1233: The following error occurred while executing this line:
/var/lib/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:876: There were test failures: 323 suites, 1376 tests, 1 error, 1 failure, 35 ignored (6 assumptions)
Total time: 61 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure