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/09/12 13:08:22 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 816 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/816/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
2 tests failed.
REGRESSION: org.apache.solr.client.solrj.SolrExampleXMLTest.testAddDelete
Error Message:
IOException occured when talking to server at: https://127.0.0.1:51724/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:51724/solr/collection1
at __randomizedtesting.SeedInfo.seed([818358B73CD04AA0:496325BDCD789976]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:168)
at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:146)
at org.apache.solr.client.solrj.SolrExampleTests.testAddDelete(SolrExampleTests.java:750)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 45 more
REGRESSION: org.apache.solr.client.solrj.SolrExampleXMLTest.testStatistics
Error Message:
IOException occured when talking to server at: https://127.0.0.1:51724/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:51724/solr/collection1
at __randomizedtesting.SeedInfo.seed([818358B73CD04AA0:762A6BD390FD9048]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:435)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.client.solrj.SolrExampleTests.testStatistics(SolrExampleTests.java:873)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 45 more
Build Log:
[...truncated 10808 lines...]
[junit4] Suite: org.apache.solr.client.solrj.SolrExampleXMLTest
[junit4] 2> 41876 T46 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 41877 T46 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleXMLTest-1378983443131
[junit4] 2> 41880 T46 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 42714 T46 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 43381 T46 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 43492 T46 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:51724
[junit4] 2> 43633 T46 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 43634 T46 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 43634 T46 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 43635 T46 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/'
[junit4] 2> 43673 T46 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 43847 T46 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 43859 T46 oasc.CoreContainer.<init> New CoreContainer 1472748900
[junit4] 2> 43860 T46 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/]
[junit4] 2> 43966 T46 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 43967 T46 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 43968 T46 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 43969 T46 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 43970 T46 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 43971 T46 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 43972 T46 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 43973 T46 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 43974 T46 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 43975 T46 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 43988 T46 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 43989 T46 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 43997 T46 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr
[junit4] 2> 44015 T46 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/
[junit4] 2> 44017 T46 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 44019 T58 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1
[junit4] 2> 44021 T58 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 44181 T58 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 44183 T58 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 44185 T58 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 44186 T58 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 44187 T58 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 44189 T58 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 44189 T58 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 44192 T58 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 44192 T58 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 44336 T58 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 44345 T58 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 44505 T58 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 44507 T58 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 44577 T58 oass.IndexSchema.readSchema [null] Schema name=example
[junit4] 2> 45577 T58 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 45612 T58 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 45627 T58 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 45711 T58 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 45711 T58 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/
[junit4] 2> 45724 T58 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66b66b36
[junit4] 2> 45727 T58 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 45728 T58 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 45729 T58 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131
[junit4] 2> 45729 T58 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index/
[junit4] 2> 45730 T58 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index' doesn't exist. Creating new index...
[junit4] 2> 45730 T58 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index
[junit4] 2> 45732 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@3f48f4ac
[junit4] 2> 45733 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 45733 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: 0 msec to checkpoint
[junit4] 2> 45734 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: init: create=true
[junit4] 2> 45734 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@4eb768a9
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 45735 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 45735 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 45736 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: index before flush
[junit4] 2> 45736 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 startFullFlush
[junit4] 2> 45737 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 45737 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 finishFullFlush success=true
[junit4] 2> 45738 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: apply all deletes during flush
[junit4] 2> 45739 T58 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-31-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@6b38579e minGen=9223372036854775807 packetCount=0
[junit4] 2> 45739 T58 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-31-thread-1]: now merge
[junit4] 2> 45740 T58 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-31-thread-1]: index:
[junit4] 2> 45740 T58 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-31-thread-1]: no more merges pending; now return
[junit4] 2> 45740 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: waitForMerges
[junit4] 2> 45741 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: waitForMerges done
[junit4] 2> 45741 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: now call final commit()
[junit4] 2> 45742 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: start
[junit4] 2> 45742 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: enter lock
[junit4] 2> 45743 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: now prepare
[junit4] 2> 45743 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: prepareCommit: flush
[junit4] 2> 45744 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: index before flush
[junit4] 2> 45744 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 startFullFlush
[junit4] 2> 45745 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 45749 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: apply all deletes during flush
[junit4] 2> 45749 T58 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-31-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@6b38579e minGen=9223372036854775807 packetCount=0
[junit4] 2> 45754 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 finishFullFlush success=true
[junit4] 2> 45755 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: startCommit(): start
[junit4] 2> 45755 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: startCommit index= changeCount=1
[junit4] 2> 45766 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: done all syncs: []
[junit4] 2> 45767 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: pendingCommit != null
[junit4] 2> 45784 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 45784 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 45785 T58 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_1,generation=1}
[junit4] 2> 45785 T58 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 45786 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: 1 msec to checkpoint
[junit4] 2> 45786 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: commit: done
[junit4] 2> 45787 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: at close:
[junit4] 2> 45788 T58 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 45788 T58 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 45789 T58 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 45790 T58 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 45790 T58 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 45800 T58 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 45801 T58 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 45802 T58 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 45804 T58 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 45805 T58 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 45806 T58 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 45807 T58 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 45808 T58 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 45808 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 45809 T58 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 45809 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 45810 T58 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 45811 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 45811 T58 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 45812 T58 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 45813 T58 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 45820 T58 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 45821 T58 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 45822 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 45822 T58 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 45823 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 45824 T58 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 45824 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 45825 T58 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 45830 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 45831 T58 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 45831 T58 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 45832 T58 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 45845 T58 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 45847 T58 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 45850 T58 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 45860 T58 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 45861 T58 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 45863 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@3f48f4ac
[junit4] 2> 45863 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: init: load commit "segments_1"
[junit4] 2> 45864 T58 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_1,generation=1}
[junit4] 2> 45864 T58 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 45865 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 45865 T58 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-31-thread-1]: 0 msec to checkpoint
[junit4] 2> 45866 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: init: create=false
[junit4] 2> 45866 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb)
[junit4] 2> index=
[junit4] 2> version=5.0-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_50
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@633bd33
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 45867 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: flush at getReader
[junit4] 2> 45867 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 startFullFlush
[junit4] 2> 45868 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 45868 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: apply all deletes during flush
[junit4] 2> 45869 T58 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-31-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=9223372036854775807 packetCount=0
[junit4] 2> 45870 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 45871 T58 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-31-thread-1]: coreLoadExecutor-31-thread-1 finishFullFlush success=true
[junit4] 2> 45871 T58 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-31-thread-1]: getReader took 4 msec
[junit4] 2> 45872 T58 oass.SolrIndexSearcher.<init> Opening Searcher@691e5879 main
[junit4] 2> 45872 T58 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 45873 T58 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> 45874 T58 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 45875 T58 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 45922 T58 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 45923 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@691e5879 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C25 name=collection1 org.apache.solr.core.SolrCore@53553527
[junit4] 2> 45926 T59 C25 oasc.SolrCore.execute [collection1] webapp=null path=null params={event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml&distrib=false} hits=0 status=0 QTime=2
[junit4] 2> 45927 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 45927 T59 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 45928 T59 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 45932 T59 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@691e5879 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 45937 T58 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 45939 T46 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 45939 T46 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 45940 T46 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#51724
[junit4] 2> 45960 T46 oas.SolrTestCaseJ4.setUp ###Starting testGetEmptyResults
[junit4] 2> 45962 T46 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> ASYNC NEW_CORE C26 name=collection1 org.apache.solr.core.SolrCore@53553527
[junit4] 2> 47460 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47462 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 47463 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47463 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: flush at getReader
[junit4] 2> 47464 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57 startFullFlush
[junit4] 2> 47465 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47465 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57: flush naked frozen global deletes
[junit4] 2> 47466 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: push deletes 1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
[junit4] 2> 47468 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 47469 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: apply all deletes during flush
[junit4] 2> 47470 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=9223372036854775807 packetCount=1
[junit4] 2> 47471 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 47473 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 47474 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57 finishFullFlush success=true
[junit4] 2> 47475 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: getReader took 12 msec
[junit4] 2> 47478 T57 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1445968948717682688)} 0 30
[junit4] 2> 47697 T53 C26 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 47699 T53 C26 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 47700 T53 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47701 T53 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 47702 T53 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47703 T53 C26 oass.SolrIndexSearcher.<init> Opening Searcher@fec6b04 main
[junit4] 2> 47706 T53 C26 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 47706 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@fec6b04 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 47707 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 47713 T59 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fec6b04 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 47715 T53 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 18
[junit4] 2> 47740 T55 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[id1 (1445968948997652480)]} 0 14
[junit4] 2> 47752 T56 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[id2 (1445968949020721152)]} 0 3
[junit4] 2> 47762 T52 C26 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 47764 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: start
[junit4] 2> 47764 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: enter lock
[junit4] 2> 47765 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: now prepare
[junit4] 2> 47766 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: prepareCommit: flush
[junit4] 2> 47767 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: index before flush
[junit4] 2> 47768 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 startFullFlush
[junit4] 2> 47769 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=2 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47770 T52 C26 oasu.LoggingInfoStream.message [DWFC][qtp423757513-52]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 1 deleted terms (unique count=1) bytesUsed=167, segment=_0, aborting=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 47770 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flush postings as segment _0 numDocs=2
[junit4] 2> 47775 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: new segment has 0 deleted docs
[junit4] 2> 47776 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 47777 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.nvm, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4] 2> 47777 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushed codec=Lucene45
[junit4] 2> 47789 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushed: segment=_0 ramUsed=0.08 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,336.617
[junit4] 2> 47790 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 47795 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: publishFlushedSegment
[junit4] 2> 47796 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: push deletes 2 deleted terms (unique count=2) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
[junit4] 2> 47797 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: publish sets newSegment delGen=5 seg=_0(5.0):C2
[junit4] 2> 47797 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: now checkpoint "_0(5.0):C2" [1 segments ; isCommit = false]
[junit4] 2> 47798 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 0 msec to checkpoint
[junit4] 2> 47799 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: apply all deletes during flush
[junit4] 2> 47799 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes: infos=[_0(5.0):C2] packetCount=1
[junit4] 2> 47800 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes took 1 msec
[junit4] 2> 47800 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=6 packetCount=1
[junit4] 2> 47801 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 47802 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 finishFullFlush success=true
[junit4] 2> 47803 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: findMerges: 1 segments
[junit4] 2> 47804 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: seg=_0(5.0):C2 size=0.001 MB [floored]
[junit4] 2> 47804 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 47805 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: now merge
[junit4] 2> 47806 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: index: _0(5.0):C2
[junit4] 2> 47806 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: no more merges pending; now return
[junit4] 2> 47807 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: startCommit(): start
[junit4] 2> 47807 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: startCommit index=_0(5.0):C2 changeCount=3
[junit4] 2> 47808 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4] 2> 47820 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: pendingCommit != null
[junit4] 2> 47826 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: wrote segments file "segments_2"
[junit4] 2> 47827 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: now checkpoint "_0(5.0):C2" [1 segments ; isCommit = true]
[junit4] 2> 47828 T52 C26 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_2,generation=2}
[junit4] 2> 47829 T52 C26 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 47829 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 47830 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "segments_1"
[junit4] 2> 47831 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 3 msec to checkpoint
[junit4] 2> 47831 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: done
[junit4] 2> 47833 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47834 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 47834 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: flush at getReader
[junit4] 2> 47835 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 startFullFlush
[junit4] 2> 47836 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47837 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: apply all deletes during flush
[junit4] 2> 47838 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes: no deletes; skipping
[junit4] 2> 47839 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=6 packetCount=0
[junit4] 2> 47852 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)
[junit4] 2> 47854 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 finishFullFlush success=true
[junit4] 2> 47854 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: getReader took 20 msec
[junit4] 2> 47860 T52 C26 oass.SolrIndexSearcher.<init> Opening Searcher@469681e0 main
[junit4] 2> 47861 T52 C26 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 47861 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@469681e0 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)}
[junit4] 2> 47862 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 47867 T59 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@469681e0 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C2)}
[junit4] 2> 47871 T52 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 108
[junit4] 2> 47894 T54 C26 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=foofoofoo&q=*:*&wt=xml&version=2.2} hits=2 status=0 QTime=10
[junit4] 2> 47899 T46 oas.SolrTestCaseJ4.tearDown ###Ending testGetEmptyResults
[junit4] 2> 47932 T46 oas.SolrTestCaseJ4.setUp ###Starting testExampleConfig
[junit4] 2> 47942 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47942 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 47943 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47944 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: flush at getReader
[junit4] 2> 47944 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57 startFullFlush
[junit4] 2> 47945 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 47945 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57: flush naked frozen global deletes
[junit4] 2> 47946 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: push deletes 1 deleted queries bytesUsed=32 delGen=8 packetCount=1 totBytesUsed=32
[junit4] 2> 47947 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: flush: push buffered deletes: 1 deleted queries bytesUsed=32
[junit4] 2> 47947 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: apply all deletes during flush
[junit4] 2> 47948 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: applyDeletes: infos=[_0(5.0):C2] packetCount=1
[junit4] 2> 47950 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: seg=_0(5.0):C2 segGen=6 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=2 100% deleted
[junit4] 2> 47951 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: applyDeletes took 3 msec
[junit4] 2> 47951 T57 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-57]: now checkpoint "_0(5.0):C2/2" [1 segments ; isCommit = false]
[junit4] 2> 47952 T57 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-57]: 0 msec to checkpoint
[junit4] 2> 47953 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: drop 100% deleted segments: _0(5.0):C2/2
[junit4] 2> 47953 T57 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-57]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 47954 T57 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-57]: 0 msec to checkpoint
[junit4] 2> 47954 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=9223372036854775807 packetCount=1
[junit4] 2> 47955 T57 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-57]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 47956 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 47956 T57 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-57]: qtp423757513-57 finishFullFlush success=true
[junit4] 2> 47957 T57 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-57]: getReader took 13 msec
[junit4] 2> 47958 T57 C26 oass.SolrIndexSearcher.<init> Opening Searcher@703802cb realtime
[junit4] 2> 47959 T57 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1445968949220999168)} 0 20
[junit4] 2> 47984 T56 C26 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[1112211111 (1445968949260845056)]} 0 6
[junit4] 2> 47999 T52 C26 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 48000 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: start
[junit4] 2> 48001 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: enter lock
[junit4] 2> 48001 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: now prepare
[junit4] 2> 48002 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: prepareCommit: flush
[junit4] 2> 48002 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: index before flush
[junit4] 2> 48003 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 startFullFlush
[junit4] 2> 48004 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48004 T52 C26 oasu.LoggingInfoStream.message [DWFC][qtp423757513-52]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 48005 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flush postings as segment _1 numDocs=1
[junit4] 2> 48009 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: new segment has 0 deleted docs
[junit4] 2> 48010 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 48010 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushedFiles=[_1.nvm, _1_Lucene41_0.pos, _1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 48011 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushed codec=Lucene45
[junit4] 2> 48012 T52 C26 oasu.LoggingInfoStream.message [DWPT][qtp423757513-52]: flushed: segment=_1 ramUsed=0.079 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,042.322
[junit4] 2> 48012 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 48013 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: publishFlushedSegment
[junit4] 2> 48013 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
[junit4] 2> 48014 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: publish sets newSegment delGen=11 seg=_1(5.0):C1
[junit4] 2> 48015 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: now checkpoint "_1(5.0):C1" [1 segments ; isCommit = false]
[junit4] 2> 48015 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 0 msec to checkpoint
[junit4] 2> 48016 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: apply all deletes during flush
[junit4] 2> 48017 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes: infos=[_1(5.0):C1] packetCount=1
[junit4] 2> 48017 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes took 1 msec
[junit4] 2> 48018 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=1
[junit4] 2> 48019 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 48019 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 finishFullFlush success=true
[junit4] 2> 48020 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: findMerges: 1 segments
[junit4] 2> 48021 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: seg=_1(5.0):C1 size=0.001 MB [floored]
[junit4] 2> 48022 T52 C26 oasu.LoggingInfoStream.message [TMP][qtp423757513-52]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 48022 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: now merge
[junit4] 2> 48023 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: index: _1(5.0):C1
[junit4] 2> 48023 T52 C26 oasu.LoggingInfoStream.message [CMS][qtp423757513-52]: no more merges pending; now return
[junit4] 2> 48024 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: startCommit(): start
[junit4] 2> 48025 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: startCommit index=_1(5.0):C1 changeCount=8
[junit4] 2> 48026 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: done all syncs: [_1.fdx, _1_Lucene41_0.pos, _1.nvm, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1.nvd, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 48026 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: pendingCommit != null
[junit4] 2> 48027 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: wrote segments file "segments_3"
[junit4] 2> 48028 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: now checkpoint "_1(5.0):C1" [1 segments ; isCommit = true]
[junit4] 2> 48028 T52 C26 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_3,generation=3}
[junit4] 2> 48029 T52 C26 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 48030 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 48030 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.fnm"
[junit4] 2> 48031 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.doc"
[junit4] 2> 48031 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 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> 48032 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.pos"
[junit4] 2> 48033 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 48034 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.nvd"
[junit4] 2> 48034 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 48035 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "segments_2"
[junit4] 2> 48036 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.fdx"
[junit4] 2> 48036 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.si"
[junit4] 2> 48037 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.nvm"
[junit4] 2> 48037 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.tim"
[junit4] 2> 48038 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 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> 48038 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.fdt"
[junit4] 2> 48039 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 48039 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.tip"
[junit4] 2> 48041 T52 C26 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 12 msec to checkpoint
[junit4] 2> 48041 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: commit: done
[junit4] 2> 48042 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48042 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 48043 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: flush at getReader
[junit4] 2> 48044 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 startFullFlush
[junit4] 2> 48044 T52 C26 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48045 T52 C26 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: apply all deletes during flush
[junit4] 2> 48045 T52 C26 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: applyDeletes: no deletes; skipping
[junit4] 2> ASYNC NEW_CORE C27 name=collection1 org.apache.solr.core.SolrCore@53553527
[junit4] 2> 48046 T52 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-52]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=0
[junit4] 2> 48059 T52 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)
[junit4] 2> 48060 T52 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-52]: qtp423757513-52 finishFullFlush success=true
[junit4] 2> 48060 T52 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-52]: getReader took 17 msec
[junit4] 2> 48061 T52 C27 oass.SolrIndexSearcher.<init> Opening Searcher@129c5a28 main
[junit4] 2> 48062 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 48063 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.doc"
[junit4] 2> 48064 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 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> 48064 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 48065 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.pos"
[junit4] 2> 48065 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_0_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 48066 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete pending file _0.nvd
[junit4] 2> 48066 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.nvd"
[junit4] 2> 48067 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0.nvd": java.io.IOException: MockDirectoryWrapper: file "_0.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 48068 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 48069 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0_Lucene41_0.tim"
[junit4] 2> 48069 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: 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> 48070 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete pending file _0.fdt
[junit4] 2> 48070 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: delete "_0.fdt"
[junit4] 2> 48071 T52 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-52]: unable to remove file "_0.fdt": java.io.IOException: MockDirectoryWrapper: file "_0.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 48072 T52 C27 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 48072 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@129c5a28 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 48073 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 48079 T59 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@129c5a28 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4] 2> 48080 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _0_Lucene41_0.doc
[junit4] 2> 48081 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 48083 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _0_Lucene41_0.pos
[junit4] 2> 48084 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_0_Lucene41_0.pos"
[junit4] 2> 48084 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _0.nvd
[junit4] 2> 48084 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_0.nvd"
[junit4] 2> 48085 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _0_Lucene41_0.tim
[junit4] 2> 48085 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 48085 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _0.fdt
[junit4] 2> 48085 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_0.fdt"
[junit4] 2> 48086 T52 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 87
[junit4] 2> 48106 T53 C27 oasu.DirectUpdateHandler2.commit start commit{,optimize=true,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 48109 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: forceMerge: index now _1(5.0):C1
[junit4] 2> 48111 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: now flush at forceMerge
[junit4] 2> 48112 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: start flush: applyAllDeletes=true
[junit4] 2> 48113 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: index before flush _1(5.0):C1
[junit4] 2> 48114 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 startFullFlush
[junit4] 2> 48115 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48116 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 finishFullFlush success=true
[junit4] 2> 48117 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: apply all deletes during flush
[junit4] 2> 48118 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: applyDeletes: no deletes; skipping
[junit4] 2> 48119 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=0
[junit4] 2> 48129 T53 C27 oasu.LoggingInfoStream.message [TMP][qtp423757513-53]: findForcedMerges maxSegmentCount=1 infos=_1(5.0):C1 segmentsToMerge={_1(5.0):C1=true}
[junit4] 2> 48130 T53 C27 oasu.LoggingInfoStream.message [TMP][qtp423757513-53]: eligible=[_1(5.0):C1]
[junit4] 2> 48131 T53 C27 oasu.LoggingInfoStream.message [TMP][qtp423757513-53]: forceMergeRunning=false
[junit4] 2> 48132 T53 C27 oasu.LoggingInfoStream.message [TMP][qtp423757513-53]: add final merge=_1(5.0):C1
[junit4] 2> 48132 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: add merge to pendingMerges: _1(5.0):C1 [total 1 pending]
[junit4] 2> 48133 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: registerMerge merging= []
[junit4] 2> 48135 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: registerMerge info=_1(5.0):C1
[junit4] 2> 48141 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: now merge
[junit4] 2> 48142 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: index: _1(5.0):C1
[junit4] 2> 48143 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: consider merge _1(5.0):C1
[junit4] 2> 48144 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: launch new thread [Lucene Merge Thread #0]
[junit4] 2> 48163 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: set priority of merge thread Lucene Merge Thread #0 to 6
[junit4] 2> 48165 T53 C27 oasu.LoggingInfoStream.message [CMS][qtp423757513-53]: no more merges pending; now return
[junit4] 2> 48171 T62 oasu.LoggingInfoStream.message [CMS][Lucene Merge Thread #0]: merge thread: start
[junit4] 2> 48172 T62 oasu.LoggingInfoStream.message [BD][Lucene Merge Thread #0]: applyDeletes: no deletes; skipping
[junit4] 2> 48173 T62 oasu.LoggingInfoStream.message [BD][Lucene Merge Thread #0]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=0
[junit4] 2> 48173 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: merge seg=_2 _1(5.0):C1
[junit4] 2> 48174 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: now merge
[junit4] 2> merge=_1(5.0):C1
[junit4] 2> index=_1(5.0):C1
[junit4] 2> 48174 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: merging _1(5.0):C1
[junit4] 2> 48175 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: seg=_1(5.0):C1 no deletes
[junit4] 2> 48175 T62 oasu.LoggingInfoStream.message [SM][Lucene Merge Thread #0]: merge store matchedCount=1 vs 1
[junit4] 2> 48176 T62 oasu.LoggingInfoStream.message [SM][Lucene Merge Thread #0]: 0 msec to merge stored fields [1 docs]
[junit4] 2> 48179 T62 oasu.LoggingInfoStream.message [SM][Lucene Merge Thread #0]: 2 msec to merge postings [1 docs]
[junit4] 2> 48180 T62 oasu.LoggingInfoStream.message [SM][Lucene Merge Thread #0]: 0 msec to merge doc values [1 docs]
[junit4] 2> 48180 T62 oasu.LoggingInfoStream.message [SM][Lucene Merge Thread #0]: 0 msec to merge norms [1 docs]
[junit4] 2> 48181 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: merge codec=Lucene45 docCount=1; merged segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 48182 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: merged segment size=0.001 MB vs estimate=0.001 MB
[junit4] 2> 48183 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: commitMerge: _1(5.0):C1 index=_1(5.0):C1
[junit4] 2> 48183 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: commitMergeDeletes _1(5.0):C1
[junit4] 2> 48183 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: no new deletes since merge started
[junit4] 2> 48184 T62 oasu.LoggingInfoStream.message [IFD][Lucene Merge Thread #0]: now checkpoint "_2(5.0):C1" [1 segments ; isCommit = false]
[junit4] 2> 48184 T62 oasu.LoggingInfoStream.message [IFD][Lucene Merge Thread #0]: 0 msec to checkpoint
[junit4] 2> 48185 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: after commitMerge: _2(5.0):C1
[junit4] 2> 48185 T62 oasu.LoggingInfoStream.message [TMP][Lucene Merge Thread #0]: findForcedMerges maxSegmentCount=1 infos=_2(5.0):C1 segmentsToMerge={_1(5.0):C1=true, _2(5.0):C1=false}
[junit4] 2> 48185 T62 oasu.LoggingInfoStream.message [TMP][Lucene Merge Thread #0]: already merged
[junit4] 2> 48186 T62 oasu.LoggingInfoStream.message [IW][Lucene Merge Thread #0]: merge time 14 msec for 1 docs
[junit4] 2> 48186 T62 oasu.LoggingInfoStream.message [CMS][Lucene Merge Thread #0]: merge thread: done
[junit4] 2> 48186 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: start
[junit4] 2> 48188 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: enter lock
[junit4] 2> 48188 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: now prepare
[junit4] 2> 48189 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: prepareCommit: flush
[junit4] 2> 48189 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: index before flush _2(5.0):C1
[junit4] 2> 48190 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 startFullFlush
[junit4] 2> 48190 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48191 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: apply all deletes during flush
[junit4] 2> 48191 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: applyDeletes: no deletes; skipping
[junit4] 2> 48192 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=0
[junit4] 2> 48193 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 finishFullFlush success=true
[junit4] 2> 48193 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: startCommit(): start
[junit4] 2> 48193 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: startCommit index=_2(5.0):C1 changeCount=11
[junit4] 2> 48194 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: 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> 48195 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: pendingCommit != null
[junit4] 2> 48195 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: wrote segments file "segments_4"
[junit4] 2> 48196 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: now checkpoint "_2(5.0):C1" [1 segments ; isCommit = true]
[junit4] 2> 48197 T53 C27 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e2fa8b3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@130c14cb),segFN=segments_4,generation=4}
[junit4] 2> 48198 T53 C27 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 48198 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 48199 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.fdx"
[junit4] 2> 48199 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1_Lucene41_0.pos"
[junit4] 2> 48200 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: unable to remove file "_1_Lucene41_0.pos": java.io.IOException: MockDirectoryWrapper: file "_1_Lucene41_0.pos" is still open: cannot delete; Will re-try later.
[junit4] 2> 48200 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.nvm"
[junit4] 2> 48201 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1_Lucene41_0.doc"
[junit4] 2> 48201 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: 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> 48202 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.fdt"
[junit4] 2> 48202 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 48203 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.si"
[junit4] 2> 48203 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1_Lucene41_0.tim"
[junit4] 2> 48204 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: 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> 48205 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.nvd"
[junit4] 2> 48205 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: unable to remove file "_1.nvd": java.io.IOException: MockDirectoryWrapper: file "_1.nvd" is still open: cannot delete; Will re-try later.
[junit4] 2> 48206 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1_Lucene41_0.tip"
[junit4] 2> 48207 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "_1.fnm"
[junit4] 2> 48207 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: delete "segments_3"
[junit4] 2> 48208 T53 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-53]: 12 msec to checkpoint
[junit4] 2> 48209 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: commit: done
[junit4] 2> 48209 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48210 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 48210 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: flush at getReader
[junit4] 2> 48211 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 startFullFlush
[junit4] 2> 48211 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48212 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: apply all deletes during flush
[junit4] 2> 48212 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: applyDeletes: no deletes; skipping
[junit4] 2> 48213 T53 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-53]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=12 packetCount=0
[junit4] 2> 48215 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: return reader version=9 reader=StandardDirectoryReader(segments_4:9:nrt _2(5.0):C1)
[junit4] 2> 48216 T53 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-53]: qtp423757513-53 finishFullFlush success=true
[junit4] 2> 48216 T53 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-53]: getReader took 6 msec
[junit4] 2> 48217 T53 C27 oass.SolrIndexSearcher.<init> Opening Searcher@17f6a75d main
[junit4] 2> 48218 T53 C27 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 48218 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@17f6a75d main{StandardDirectoryReader(segments_4:9:nrt _2(5.0):C1)}
[junit4] 2> 48219 T59 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 48222 T59 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17f6a75d main{StandardDirectoryReader(segments_4:9:nrt _2(5.0):C1)}
[junit4] 2> 48224 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _1_Lucene41_0.pos
[junit4] 2> 48224 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_1_Lucene41_0.pos"
[junit4] 2> 48224 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 48224 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 48225 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _1.fdt
[junit4] 2> 48225 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_1.fdt"
[junit4] 2> 48225 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 48225 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 48226 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete pending file _1.nvd
[junit4] 2> 48226 T59 oasu.LoggingInfoStream.message [IFD][searcherExecutor-32-thread-1]: delete "_1.nvd"
[junit4] 2> 48227 T53 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={optimize=true&waitSearcher=true&maxSegments=1&wt=xml&version=2.2} {optimize=} 0 121
[junit4] 2> 48237 T57 C27 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=id:1112211111&wt=xml&version=2.2} hits=1 status=0 QTime=2
[junit4] 2> 48271 T55 C27 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[2 (1445968949549203456), 3 (1445968949559689216), 4 (1445968949561786368), 5 (1445968949563883520)]} 0 19
[junit4] 2> 48285 T56 C27 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 48286 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: commit: start
[junit4] 2> 48286 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: commit: enter lock
[junit4] 2> 48286 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: commit: now prepare
[junit4] 2> 48287 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: prepareCommit: flush
[junit4] 2> 48288 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: index before flush _2(5.0):C1
[junit4] 2> 48289 T56 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-56]: qtp423757513-56 startFullFlush
[junit4] 2> 48290 T56 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-56]: anyChanges? numDocsInRam=4 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 48291 T56 C27 oasu.LoggingInfoStream.message [DWFC][qtp423757513-56]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 3 deleted terms (unique count=3) bytesUsed=495, segment=_3, aborting=false, numDocsInRAM=4, deleteQueue=DWDQ: [ generation: 10 ]]
[junit4] 2> 48292 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: flush postings as segment _3 numDocs=4
[junit4] 2> 48296 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: new segment has 0 deleted docs
[junit4] 2> 48297 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 48297 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: 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> 48298 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: flushed codec=Lucene45
[junit4] 2> 48299 T56 C27 oasu.LoggingInfoStream.message [DWPT][qtp423757513-56]: flushed: segment=_3 ramUsed=0.072 MB newFlushedSize(includes docstores)=0.002 MB docs/MB=2,327.583
[junit4] 2> 48299 T56 C27 oasu.LoggingInfoStream.message [DW][qtp423757513-56]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 48300 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: publishFlushedSegment
[junit4] 2> 48300 T56 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-56]: push deletes 4 deleted terms (unique count=4) bytesUsed=1024 delGen=18 packetCount=1 totBytesUsed=1024
[junit4] 2> 48301 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: publish sets newSegment delGen=19 seg=_3(5.0):C4
[junit4] 2> 48301 T56 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-56]: now checkpoint "_2(5.0):C1 _3(5.0):C4" [2 segments ; isCommit = false]
[junit4] 2> 48302 T56 C27 oasu.LoggingInfoStream.message [IFD][qtp423757513-56]: 0 msec to checkpoint
[junit4] 2> 48302 T56 C27 oasu.LoggingInfoStream.message [IW][qtp423757513-56]: apply all deletes during flush
[junit4] 2> 48303 T56 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-56]: applyDeletes: infos=[_2(5.0):C1, _3(5.0):C4] packetCount=1
[junit4] 2> 48304 T56 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-56]: seg=_2(5.0):C1 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=0
[junit4] 2> 48304 T56 C27 oasu.LoggingInfoStream.message [BD][qtp423757513-56]: applyDeletes took 1 msec
[junit4] 2> 48305 T56 C27 oasu.LoggingInfoStream.mes
[...truncated too long message...]
ecutor-32-thread-1]: delete "_13.fdt"
[junit4] 2> 461464 T52 C44 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 54
[junit4] 2> 461478 T53 C44 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2&rows=2} hits=2 status=0 QTime=1
[junit4] 2> 461481 T46 oas.SolrTestCaseJ4.tearDown ###Ending testUnicode
[junit4] 2> 461500 T46 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1472748900
[junit4] 2> 461503 T46 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@53553527
[junit4] 2> 461554 T46 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=59,autocommit maxTime=15000ms,autocommits=2,soft autocommits=3,optimizes=2,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=1,cumulative_adds=134,cumulative_deletesById=2,cumulative_deletesByQuery=28,cumulative_errors=1}
[junit4] 2> 461555 T46 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 461555 T46 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 461556 T46 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> ASYNC NEW_CORE C45 name=collection1 org.apache.solr.core.SolrCore@53553527
[junit4] 2> 461559 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: now flush at close waitForMerges=true
[junit4] 2> 461560 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 461561 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: index before flush _14(5.0):C2
[junit4] 2> 461561 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker startFullFlush
[junit4] 2> 461562 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 461562 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker finishFullFlush success=true
[junit4] 2> 461563 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: apply all deletes during flush
[junit4] 2> 461563 T46 C45 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 461564 T46 C45 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=233 packetCount=0
[junit4] 2> 461564 T46 C45 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: now merge
[junit4] 2> 461565 T46 C45 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: index: _14(5.0):C2
[junit4] 2> 461565 T46 C45 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: no more merges pending; now return
[junit4] 2> 461566 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: waitForMerges
[junit4] 2> 461566 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: waitForMerges done
[junit4] 2> 461566 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: now call final commit()
[junit4] 2> 461567 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: commit: start
[junit4] 2> 461567 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: commit: enter lock
[junit4] 2> 461568 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: commit: now prepare
[junit4] 2> 461568 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: prepareCommit: flush
[junit4] 2> 461569 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: index before flush _14(5.0):C2
[junit4] 2> 461569 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker startFullFlush
[junit4] 2> 461570 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 461570 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: apply all deletes during flush
[junit4] 2> 461571 T46 C45 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 461572 T46 C45 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@2eca6273 minGen=233 packetCount=0
[junit4] 2> 461572 T46 C45 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker finishFullFlush success=true
[junit4] 2> 461573 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: startCommit(): start
[junit4] 2> 461573 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: skip startCommit(): no changes pending
[junit4] 2> 461574 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 461574 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: commit: done
[junit4] 2> 461574 T46 C45 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[818358B73CD04AA0]-worker]: at close: _14(5.0):C2
[junit4] 2> 461577 T46 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 461578 T46 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 461578 T46 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131;done=false>>]
[junit4] 2> 461578 T46 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131
[junit4] 2> 461579 T46 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index;done=false>>]
[junit4] 2> 461579 T46 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1378983443131/index
[junit4] 2> 461581 T46 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 461643 T46 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Asserting, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=en_IN, timezone=Pacific/Galapagos
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_40 (64-bit)/cpus=2,threads=1,free=17975816,total=49381376
[junit4] 2> NOTE: All tests run in this JVM: [MultiCoreEmbeddedTest, SolrExceptionTest, ClientUtilsTest, NamedListTest, TestSpellCheckResponse, LargeVolumeEmbeddedTest, SolrExampleXMLTest]
[junit4] Completed in 419.92s, 26 tests, 2 errors <<< FAILURES!
[...truncated 127 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:396: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:376: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:202: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:455: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1230: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:873: There were test failures: 46 suites, 272 tests, 2 errors
Total time: 108 minutes 25 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 817 -
Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/817/
Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
collection already exists: awholynewcollection_1
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: collection already exists: awholynewcollection_1
at __randomizedtesting.SeedInfo.seed([94D4FD1F82B70978:15327307F5E86944]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:424)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.impl.LBHttpSolrServer.request(LBHttpSolrServer.java:268)
at org.apache.solr.client.solrj.impl.CloudSolrServer.request(CloudSolrServer.java:663)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1572)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1586)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:481)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:152)
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 9668 lines...]
[junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4] 2> 1097586 T2912 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /vpar/
[junit4] 2> 1097601 T2912 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-CollectionsAPIDistributedZkTest-1379004210130
[junit4] 2> 1097603 T2912 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1097604 T2913 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1097608 T2912 oasc.ZkTestServer.run start zk server on port:50037
[junit4] 2> 1097615 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1097617 T2914 oazs.NIOServerCnxn.doIO WARN Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
[junit4] 2> 1099404 T2916 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37f712b2 name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1099405 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1099406 T2912 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1099415 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1099419 T2921 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c0f8972 name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1099420 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1099420 T2912 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 1099428 T2912 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 1099438 T2912 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 1099446 T2912 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 1099453 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 1099455 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 1099468 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 1099469 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 1099478 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1099480 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1099487 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 1099488 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 1099497 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 1099498 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 1099506 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 1099507 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 1099516 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 1099518 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 1099525 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1099526 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1099535 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 1099536 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 1099544 T2912 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 1099544 T2912 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 1100076 T2912 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1100102 T2912 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50041
[junit4] 2> 1100104 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1100104 T2912 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1100105 T2912 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081
[junit4] 2> 1100105 T2912 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/'
[junit4] 2> 1100160 T2912 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/solr.xml
[junit4] 2> 1100249 T2912 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1100249 T2912 oasc.CoreContainer.<init> New CoreContainer 1048505312
[junit4] 2> 1100249 T2912 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/]
[junit4] 2> 1100251 T2912 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1100252 T2912 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1100252 T2912 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1100253 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1100254 T2912 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1100254 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1100255 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1100256 T2912 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1100256 T2912 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1100257 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1100286 T2912 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 1100287 T2912 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 1100287 T2912 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50037/solr
[junit4] 2> 1100288 T2912 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1100292 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1100298 T2932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c694fa2 name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1100300 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1100304 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1100324 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1100330 T2934 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a8bc1b8 name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1100335 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1100338 T2912 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1100353 T2912 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1100363 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1100369 T2912 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50041_vpar
[junit4] 2> 1100371 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50041_vpar
[junit4] 2> 1100381 T2912 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1100398 T2912 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1100411 T2912 oasc.Overseer.start Overseer (id=90374419915669507-127.0.0.1:50041_vpar-n_0000000000) starting
[junit4] 2> 1100424 T2912 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1100436 T2936 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1100438 T2912 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1100445 T2912 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1100451 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1100462 T2935 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1100472 T2912 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081
[junit4] 2> 1100674 T2912 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/conf/
[junit4] 2> 1100686 T2912 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1100688 T2912 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1100689 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1100690 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1100717 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4] 2> 1100721 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1100730 T2939 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60823f2a name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1100731 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1100738 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1100750 T2912 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4] 2> 1101300 T2912 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1101309 T2912 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50045
[junit4] 2> 1101311 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1101312 T2912 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1101313 T2912 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282
[junit4] 2> 1101313 T2912 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/'
[junit4] 2> 1101363 T2912 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/solr.xml
[junit4] 2> 1101469 T2912 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1101469 T2912 oasc.CoreContainer.<init> New CoreContainer 551861814
[junit4] 2> 1101470 T2912 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/]
[junit4] 2> 1101472 T2912 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1101473 T2912 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1101473 T2912 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1101473 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1101474 T2912 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1101474 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1101475 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1101475 T2912 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1101476 T2912 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1101476 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1101497 T2912 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 1101497 T2912 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 1101498 T2912 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50037/solr
[junit4] 2> 1101498 T2912 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1101500 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1101506 T2950 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@632645e1 name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1101507 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1101513 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1101535 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1101540 T2952 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7291e78c name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1101540 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1101551 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1102560 T2912 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50045_vpar
[junit4] 2> 1102563 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50045_vpar
[junit4] 2> 1102572 T2939 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1102572 T2952 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1102572 T2934 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1102586 T2912 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282
[junit4] 2> 1102776 T2912 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/conf/
[junit4] 2> 1102783 T2912 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1102784 T2912 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1102785 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1102785 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1103259 T2912 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1103264 T2912 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50048
[junit4] 2> 1103266 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1103267 T2912 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1103268 T2912 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330
[junit4] 2> 1103269 T2912 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/'
[junit4] 2> 1103311 T2912 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/solr.xml
[junit4] 2> 1103460 T2912 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1103461 T2912 oasc.CoreContainer.<init> New CoreContainer 962840099
[junit4] 2> 1103461 T2912 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/]
[junit4] 2> 1103464 T2912 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1103465 T2912 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1103466 T2912 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1103466 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1103467 T2912 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1103468 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1103468 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1103469 T2912 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1103469 T2912 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1103470 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1103499 T2912 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 1103500 T2912 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 1103501 T2912 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50037/solr
[junit4] 2> 1103501 T2912 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1103504 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1104329 T2964 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d14a66a name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1104334 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1104341 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1104367 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1104372 T2966 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2954c8dc name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1104373 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1104384 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1105394 T2912 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50048_vpar
[junit4] 2> 1105397 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50048_vpar
[junit4] 2> 1105403 T2966 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1105403 T2934 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1105404 T2952 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1105404 T2939 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1105414 T2912 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330
[junit4] 2> 1105637 T2912 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/conf/
[junit4] 2> 1105651 T2912 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1105652 T2912 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1105652 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1105653 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1106118 T2912 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1106127 T2912 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50051
[junit4] 2> 1106129 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1106130 T2912 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1106131 T2912 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196
[junit4] 2> 1106131 T2912 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/'
[junit4] 2> 1106193 T2912 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/solr.xml
[junit4] 2> 1106345 T2912 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1106346 T2912 oasc.CoreContainer.<init> New CoreContainer 1745671863
[junit4] 2> 1106346 T2912 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/]
[junit4] 2> 1106349 T2912 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1106350 T2912 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1106351 T2912 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1106351 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1106352 T2912 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1106353 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1106353 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1106354 T2912 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1106354 T2912 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1106355 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1106376 T2912 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 1106377 T2912 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 1106377 T2912 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50037/solr
[junit4] 2> 1106377 T2912 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1106379 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1106387 T2978 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e94e505 name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1106388 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1106392 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1106408 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1106413 T2980 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bd0fed6 name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1106413 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1106424 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1107434 T2912 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50051_vpar
[junit4] 2> 1107437 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50051_vpar
[junit4] 2> 1107444 T2939 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1107445 T2952 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1107445 T2934 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1107446 T2966 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1107446 T2980 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1107462 T2912 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196
[junit4] 2> 1107646 T2912 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/conf/
[junit4] 2> 1107658 T2912 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1107660 T2912 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1107660 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1107661 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1108190 T2912 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1108203 T2912 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50054
[junit4] 2> 1108205 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1108205 T2912 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1108206 T2912 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214
[junit4] 2> 1108207 T2912 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/'
[junit4] 2> 1108270 T2912 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/solr.xml
[junit4] 2> 1108420 T2912 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1108420 T2912 oasc.CoreContainer.<init> New CoreContainer 1625376996
[junit4] 2> 1108421 T2912 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/]
[junit4] 2> 1108423 T2912 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1108424 T2912 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1108424 T2912 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1108425 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1108425 T2912 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1108425 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1108426 T2912 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1108426 T2912 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1108426 T2912 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1108427 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1108445 T2912 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 1108445 T2912 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 1108446 T2912 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50037/solr
[junit4] 2> 1108446 T2912 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1108448 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1108451 T2992 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@601ff4d8 name:ZooKeeperConnection Watcher:127.0.0.1:50037 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1108452 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1108457 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1108475 T2912 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1108479 T2994 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13c6d411 name:ZooKeeperConnection Watcher:127.0.0.1:50037/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1108480 T2912 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1108493 T2912 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1109502 T2912 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50054_vpar
[junit4] 2> 1109504 T2912 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50054_vpar
[junit4] 2> 1109512 T2966 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109512 T2934 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109512 T2952 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109512 T2980 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109512 T2994 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109512 T2939 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1109523 T2912 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214
[junit4] 2> 1109726 T2912 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/conf/
[junit4] 2> 1109736 T2912 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1109737 T2912 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1109738 T2912 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1109739 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1109758 T2912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1109791 T2946 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4] 2> 1109795 T2934 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1109798 T2936 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Get the message id:/overseer/collection-queue-work/qn-0000000000 message:{
[junit4] 2> "operation":"createcollection",
[junit4] 2> "numShards":"2",
[junit4] 2> "name":"nodes_used_collection",
[junit4] 2> "replicationFactor":"2"}
[junit4] 2> 1109799 T2936 oasc.OverseerCollectionProcessor.processMessage WARN OverseerCollectionProcessor.processMessage : createcollection , {
[junit4] 2> "operation":"createcollection",
[junit4] 2> "numShards":"2",
[junit4] 2> "name":"nodes_used_collection",
[junit4] 2> "replicationFactor":"2"}
[junit4] 2> 1111011 T2935 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1111012 T2935 oasc.Overseer$ClusterStateUpdater.buildCollection building a new collection: nodes_used_collection
[junit4] 2> 1111012 T2935 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with shards [shard1, shard2]
[junit4] 2> 1111021 T2952 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111022 T2934 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111022 T2980 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111022 T2966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111023 T2939 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111022 T2994 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1111038 T2936 oasc.OverseerCollectionProcessor.createCollection going to create cores replicas shardNames [shard1, shard2] , repFactor : 2
[junit4] 2> 1111038 T2936 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard1_replica1 as part of slice shard1 of collection nodes_used_collection on 127.0.0.1:50048_vpar
[junit4] 2> 1111039 T2936 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard1_replica2 as part of slice shard1 of collection nodes_used_collection on 127.0.0.1:50045_vpar
[junit4] 2> 1111040 T2936 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard2_replica1 as part of slice shard2 of collection nodes_used_collection on 127.0.0.1:50051_vpar
[junit4] 2> 1111044 T2936 oasc.OverseerCollectionProcessor.createCollection Creating shard nodes_used_collection_shard2_replica2 as part of slice shard2 of collection nodes_used_collection on 127.0.0.1:50041_vpar
[junit4] 2> 1111049 T2958 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4] 2> 1111052 T2972 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4] 2> 1111054 T2944 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4] 2> 1111056 T2928 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4] 2> 1111058 T2958 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1111059 T2944 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1111059 T2972 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1111061 T2928 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1112538 T2935 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1112544 T2935 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"nodes_used_collection_shard1_replica1",
[junit4] 2> "collection":"nodes_used_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:50048_vpar",
[junit4] 2> "base_url":"http://127.0.0.1:50048/vpar"}
[junit4] 2> 1112555 T2935 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard":"shard2",
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"nodes_used_collection_shard2_replica1",
[junit4] 2> "collection":"nodes_used_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:50051_vpar",
[junit4] 2> "base_url":"http://127.0.0.1:50051/vpar"}
[junit4] 2> 1112565 T2935 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node3",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard":"shard1",
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"nodes_used_collection_shard1_replica2",
[junit4] 2> "collection":"nodes_used_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:50045_vpar",
[junit4] 2> "base_url":"http://127.0.0.1:50045/vpar"}
[junit4] 2> 1112574 T2935 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "operation":"state",
[junit4] 2> "core_node_name":"core_node4",
[junit4] 2> "numShards":"2",
[junit4] 2> "shard":"shard2",
[junit4] 2> "roles":null,
[junit4] 2> "state":"down",
[junit4] 2> "shard_state":"active",
[junit4] 2> "core":"nodes_used_collection_shard2_replica2",
[junit4] 2> "collection":"nodes_used_collection",
[junit4] 2> "shard_range":null,
[junit4] 2> "node_name":"127.0.0.1:50041_vpar",
[junit4] 2> "base_url":"http://127.0.0.1:50041/vpar"}
[junit4] 2> 1112584 T2980 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1112584 T2966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1112584 T2939 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1112584 T2934 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1112584 T2952 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1112584 T2994 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4] 2> 1113061 T2958 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard1_replica1
[junit4] 2> 1113063 T2944 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard1_replica2
[junit4] 2> 1113065 T2958 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica1' using instanceDir: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1
[junit4] 2> 1113066 T2958 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1113066 T2944 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica2' using instanceDir: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2
[junit4] 2> 1113067 T2944 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1113067 T2958 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1113067 T2972 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard2_replica1
[junit4] 2> 1113068 T2958 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1113070 T2928 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard2_replica2
[junit4] 2> 1113071 T2972 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica1' using instanceDir: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1
[junit4] 2> 1113072 T2972 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1113073 T2944 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1113074 T2944 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1113075 T2928 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica2' using instanceDir: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2
[junit4] 2> 1113076 T2928 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1113076 T2958 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1113077 T2958 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1113076 T2972 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1113078 T2972 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1113079 T2928 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1113080 T2928 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1113082 T2944 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1113083 T2944 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1113085 T2972 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1113086 T2972 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1113086 T2928 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1113089 T2958 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1113093 T2944 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1113094 T2958 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/'
[junit4] 2> 1113099 T2944 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/'
[junit4] 2> 1113102 T2928 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1113105 T2928 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/'
[junit4] 2> 1113107 T2972 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1113138 T2972 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/'
[junit4] 2> 1113414 T2928 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 1113414 T2944 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 1113432 T2972 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 1113442 T2958 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4] 2> 1113661 T2944 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1113676 T2972 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1113676 T2944 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1113679 T2972 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1113689 T2958 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1113698 T2928 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1113698 T2958 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1113703 T2972 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1113714 T2928 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1113717 T2944 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1113731 T2958 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1113764 T2928 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1116151 T2928 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1116159 T2958 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1116174 T2972 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1116188 T2972 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1116192 T2958 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1116192 T2972 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1116202 T2958 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1116214 T2928 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1116239 T2928 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1116267 T2944 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1116293 T2944 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1116305 T2944 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1116366 T2972 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116404 T2972 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116408 T2958 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116420 T2972 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116423 T2958 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116431 T2972 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116436 T2972 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116437 T2972 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116440 T2928 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116445 T2958 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116451 T2972 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116452 T2972 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116453 T2972 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1116454 T2972 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica1] Opening new SolrCore at ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/, dataDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/data/
[junit4] 2> 1116455 T2972 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55247653
[junit4] 2> 1116457 T2972 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/data
[junit4] 2> 1116452 T2958 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116458 T2958 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116457 T2928 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116460 T2944 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116459 T2972 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/data/index/
[junit4] 2> 1116462 T2972 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica1] Solr index directory './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/data/index' doesn't exist. Creating new index...
[junit4] 2> 1116459 T2958 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116465 T2972 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1379004218196/nodes_used_collection_shard2_replica1/data/index
[junit4] 2> 1116472 T2972 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=49, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=53.28125, floorSegmentMB=1.4658203125, forceMergeDeletesPctAllowed=3.6104281907152203, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1116473 T2944 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1116474 T2972 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3b22be9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1de1b328),segFN=segments_1,generation=1}
[junit4] 2> 1116475 T2972 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116467 T2958 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116476 T2958 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116477 T2958 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1116478 T2958 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica1] Opening new SolrCore at ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/, dataDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/data/
[junit4] 2> 1116478 T2958 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55247653
[junit4] 2> 1116479 T2928 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116480 T2958 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/data
[junit4] 2> 1116483 T2928 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116483 T2928 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116484 T2928 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116485 T2958 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/data/index/
[junit4] 2> 1116486 T2958 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica1] Solr index directory '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/data/index' doesn't exist. Creating new index...
[junit4] 2> 1116490 T2944 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116493 T2958 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1379004215330/nodes_used_collection_shard1_replica1/data/index
[junit4] 2> 1116495 T2958 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=49, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=53.28125, floorSegmentMB=1.4658203125, forceMergeDeletesPctAllowed=3.6104281907152203, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1116496 T2928 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116497 T2928 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116497 T2928 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1116498 T2928 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica2] Opening new SolrCore at ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/, dataDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/data/
[junit4] 2> 1116497 T2972 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1116499 T2928 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55247653
[junit4] 2> 1116498 T2958 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d3da1c5 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@74636c8d),segFN=segments_1,generation=1}
[junit4] 2> 1116501 T2958 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116501 T2928 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/data
[junit4] 2> 1116502 T2944 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116503 T2944 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116504 T2944 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1116504 T2928 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/data/index/
[junit4] 2> 1116505 T2928 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica2] Solr index directory './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/data/index' doesn't exist. Creating new index...
[junit4] 2> 1116506 T2928 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1379004212081/nodes_used_collection_shard2_replica2/data/index
[junit4] 2> 1116507 T2928 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=49, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=53.28125, floorSegmentMB=1.4658203125, forceMergeDeletesPctAllowed=3.6104281907152203, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1116500 T2972 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1116511 T2972 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1116510 T2928 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b76ca1 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@55f13e1b),segFN=segments_1,generation=1}
[junit4] 2> 1116512 T2972 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116511 T2958 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1116513 T2972 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116515 T2972 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1116516 T2972 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116517 T2972 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116517 T2972 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1116513 T2944 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1116519 T2944 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1116513 T2928 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116520 T2944 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1116522 T2944 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica2] Opening new SolrCore at ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/, dataDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/data/
[junit4] 2> 1116522 T2944 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55247653
[junit4] 2> 1116524 T2944 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/data
[junit4] 2> 1116519 T2972 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1116525 T2972 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1116526 T2972 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1116526 T2972 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1116527 T2972 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1116528 T2972 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1116529 T2928 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1116530 T2928 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1116531 T2928 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1116532 T2928 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116533 T2928 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116533 T2928 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1116534 T2944 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/data/index/
[junit4] 2> 1116535 T2944 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica2] Solr index directory './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/data/index' doesn't exist. Creating new index...
[junit4] 2> 1116536 T2944 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1379004213282/nodes_used_collection_shard1_replica2/data/index
[junit4] 2> 1116537 T2944 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=49, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=53.28125, floorSegmentMB=1.4658203125, forceMergeDeletesPctAllowed=3.6104281907152203, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1116538 T2944 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1907596d lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@72476c5),segFN=segments_1,generation=1}
[junit4] 2> 1116539 T2944 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116514 T2958 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1116546 T2958 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1116546 T2958 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116547 T2958 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116548 T2958 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1116549 T2958 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116550 T2958 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116550 T2958 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1116552 T2958 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1116553 T2972 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1116535 T2928 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116555 T2928 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116555 T2928 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1116557 T2928 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1116558 T2928 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1116559 T2928 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1116559 T2928 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1116561 T2928 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1116562 T2928 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1116563 T2972 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1116563 T2972 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1116553 T2958 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1116564 T2958 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1116565 T2958 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1116567 T2958 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1116548 T2944 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1116567 T2958 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1116567 T2928 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1116565 T2972 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1057424642, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1116573 T2958 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1116568 T2944 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1116577 T2944 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1116578 T2944 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116579 T2944 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1116580 T2944 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1116581 T2944 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116581 T2928 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1116583 T2928 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1116583 T2944 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1116585 T2944 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1116584 T2972 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3b22be9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1de1b328),segFN=segments_1,generation=1}
[junit4] 2> 1116586 T2972 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116587 T2972 oass.SolrIndexSearcher.<init> Opening Searcher@2096ce0 main
[junit4] 2> 1116586 T2944 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1116591 T2944 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1116592 T2944 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1116592 T2944 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1116593 T2958 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1116594 T2958 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1116590 T2928 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1057424642, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1116596 T2958 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1057424642, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1116594 T2944 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1116597 T2928 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11b76ca1 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@55f13e1b),segFN=segments_1,generation=1}
[junit4] 2> 1116598 T2928 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116601 T2928 oass.SolrIndexSearcher.<init> Opening Searcher@3f8673ed main
[junit4] 2> 1116598 T2944 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1116606 T2944 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1116599 T2958 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d3da1c5 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@74636c8d),segFN=segments_1,generation=1}
[junit4] 2> 1116623 T2958 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116621 T3000 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@2096ce0 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1116624 T2958 oass.SolrIndexSearcher.<init> Opening Searcher@3073bd8c main
[junit4] 2> 1116625 T2944 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1116626 T3001 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@3f8673ed main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1116627 T2944 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1116633 T3002 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@3073bd8c main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1116637 T2958 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4] 2> 1116637 T2958 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:50048/vpar collection:nodes_used_collection shard:shard1
[junit4] 2> 1116637 T2958 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1116638 T2944 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1057424642, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1116638 T2928 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4] 2> 1116639 T2928 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:50041/vpar collection:nodes_used_collection shard:shard2
[junit4] 2> 1116640 T2928 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1116639 T2944 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1907596d lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@72476c5),segFN=segments_1,generation=1}
[junit4] 2> 1116651 T2944 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1116651 T2944 oass.SolrIndexSearcher.<init> Opening Searcher@37d5742e main
[junit4] 2> 1116657 T3003 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@37d5742e main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1116639 T2972 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4] 2> 1116658 T2972 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:50051/vpar collection:nodes_used_collection shard:shard2
[junit4] 2> 1116658 T2944 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4] 2> 1116663 T2944 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:50045/vpar collection:nodes_used_collection shard:shard1
[junit4] 2> 1116663 T2944 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1116662 T2972 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1116694 T2928 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4] 2> 1116695 T2958 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4] 2> 1116708 T2972 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4] 2> 1116726 T2944 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_el
[...truncated too long message...]
ace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard2_replica5/data
[junit4] 2> 1181540 T2912 oasc.SolrCore.close [awholynewcollection_1_shard1_replica5] CLOSING SolrCore org.apache.solr.core.SolrCore@47a3dd9e
[junit4] 2> 1181549 T2912 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> 1181550 T2912 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 1181551 T2912 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 1181551 T2912 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 1181552 T2912 oasc.SolrCore.closeSearcher [awholynewcollection_1_shard1_replica5] Closing main searcher on request.
[junit4] 2> 1181553 T2912 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 1181553 T2912 oasc.CachingDirectoryFactory.closeCacheValue looking to close ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data [CachedDir<<refCount=0;path=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data;done=false>>]
[junit4] 2> 1181554 T2912 oasc.CachingDirectoryFactory.close Closing directory: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data
[junit4] 2> 1181554 T2912 oasc.CachingDirectoryFactory.closeCacheValue looking to close ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data/index [CachedDir<<refCount=0;path=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data/index;done=false>>]
[junit4] 2> 1181554 T2912 oasc.CachingDirectoryFactory.close Closing directory: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1379004220214/awholynewcollection_1_shard1_replica5/data/index
[junit4] 2> 1181556 T3219 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=90374419915669516-127.0.0.1:50054_vpar-n_0000000004) am no longer a leader.
[junit4] 2> 1181578 T2912 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/vpar,null}
[junit4] 2> 1181652 T2912 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4] 2> 1181655 T2912 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50037 50037
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=CollectionsAPIDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=94D4FD1F82B70978 -Dtests.slow=true -Dtests.locale=fr_LU -Dtests.timezone=Mideast/Riyadh89 -Dtests.file.encoding=UTF-8
[junit4] ERROR 84.2s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: collection already exists: awholynewcollection_1
[junit4] > at __randomizedtesting.SeedInfo.seed([94D4FD1F82B70978:15327307F5E86944]:0)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:424)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrServer.request(LBHttpSolrServer.java:268)
[junit4] > at org.apache.solr.client.solrj.impl.CloudSolrServer.request(CloudSolrServer.java:663)
[junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1572)
[junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1586)
[junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:481)
[junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:152)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4] 2> 1181833 T2912 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> 84259 T2911 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4] 2> 1182861 T2994 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1182863 T2994 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> 1182863 T2994 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> NOTE: test params are: codec=Lucene45: {}, docValues:{}, sim=DefaultSimilarity, locale=fr_LU, timezone=Mideast/Riyadh89
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_40 (64-bit)/cpus=2,threads=4,free=115671040,total=240054272
[junit4] 2> NOTE: All tests run in this JVM: [ZkNodePropsTest, PreAnalyzedFieldTest, WordBreakSolrSpellCheckerTest, HighlighterConfigTest, JsonLoaderTest, SolrXmlInZkTest, ShardRoutingCustomTest, TestImplicitCoreProperties, ResponseLogComponentTest, DirectUpdateHandlerTest, TestSweetSpotSimilarityFactory, TestSolrQueryParserResource, TestSolrDeletionPolicy1, TestSurroundQueryParser, SuggesterFSTTest, MultiTermTest, TestCSVResponseWriter, DirectSolrConnectionTest, TestCloudManagedSchema, SolrInfoMBeanTest, TestPerFieldSimilarity, TestXIncludeConfig, NoCacheHeaderTest, TestAtomicUpdateErrorCases, TestPseudoReturnFields, PathHierarchyTokenizerFactoryTest, AutoCommitTest, AssignTest, TestBM25SimilarityFactory, StatsComponentTest, TestExtendedDismaxParser, TestCharFilters, TestFieldResource, TestStressLucene, TestReloadAndDeleteDocs, InfoHandlerTest, TestSuggestSpellingConverter, TestFaceting, SignatureUpdateProcessorFactoryTest, TestSchemaVersionResource, SolrIndexSplitterTest, SyncSliceTest, HighlighterTest, TestRecoveryHdfs, TestSerializedLuceneMatchVersion, PluginInfoTest, TestStressVersions, XsltUpdateRequestHandlerTest, TestJoin, TestPartialUpdateDeduplication, HdfsUnloadDistributedZkTest, DistributedSpellCheckComponentTest, SimpleFacetsTest, ShardRoutingTest, TestLFUCache, DeleteShardTest, TestSchemaResource, LegacyHTMLStripCharFilterTest, DocValuesMissingTest, TestSolrXml, CircularListTest, TestGroupingSearch, RegexBoostProcessorTest, TimeZoneUtilsTest, SuggesterTSTTest, OutputWriterTest, TestRemoteStreaming, TestQueryUtils, TestSolrCoreProperties, OpenExchangeRatesOrgProviderTest, TestNonNRTOpen, ParsingFieldUpdateProcessorsTest, CurrencyFieldXmlFileTest, TestFieldTypeCollectionResource, TestTrie, SolrCmdDistributorTest, SpellingQueryConverterTest, TestRangeQuery, LeaderElectionIntegrationTest, SpatialFilterTest, NotRequiredUniqueKeyTest, TestDFRSimilarityFactory, TermVectorComponentTest, TestDefaultSearchFieldResource, DistanceFunctionTest, TestReload, TestRTGBase, UniqFieldsUpdateProcessorFactoryTest, SystemInfoHandlerTest, HdfsCollectionsAPIDistributedZkTest, TestSolrXmlPersistor, TestRandomFaceting, DocumentAnalysisRequestHandlerTest, TestFieldCollectionResource, ChaosMonkeySafeLeaderTest, TermVectorComponentDistributedTest, MBeansHandlerTest, ExternalFileFieldSortTest, UnloadDistributedZkTest, TestReversedWildcardFilterFactory, BasicFunctionalityTest, OverseerTest, SpellCheckCollatorTest, CollectionsAPIDistributedZkTest]
[junit4] Completed in 85.58s, 1 test, 1 error <<< FAILURES!
[...truncated 680 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:396: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:376: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:189: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:455: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1230: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:873: There were test failures: 325 suites, 1446 tests, 1 error, 39 ignored (5 assumptions)
Total time: 95 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure