You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/08/23 18:48:32 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 737 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/737/
Java: 64bit/jdk1.6.0 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.embedded.SolrExampleStreamingTest.testAddDelete
Error Message:
IOException occured when talking to server at: https://127.0.0.1:54738/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:54738/solr/collection1
at __randomizedtesting.SeedInfo.seed([7E9D2317BE52487B:B67D5E1D4FFA9BAD]: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.impl.ConcurrentUpdateSolrServer.request(ConcurrentUpdateSolrServer.java:256)
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:766)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:680)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
... 46 more
Build Log:
[...truncated 10402 lines...]
[junit4] Suite: org.apache.solr.client.solrj.embedded.SolrExampleStreamingTest
[junit4] 2> 84592 T195 oas.SolrJettyTestBase.beforeSolrJettyTestBase Randomized ssl (true) and clientAuth (false)
[junit4] 2> 84594 T195 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleStreamingTest-1377276103885
[junit4] 2> 84596 T195 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 84598 T195 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 84674 T195 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1] of [SSLv2Hello, SSLv3, TLSv1]
[junit4] 2> 84686 T195 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:54738
[junit4] 2> 84688 T195 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 84689 T195 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 84689 T195 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 84690 T195 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/'
[junit4] 2> 84798 T195 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/solr.xml
[junit4] 2> 85161 T195 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 85162 T195 oasc.CoreContainer.<init> New CoreContainer 1346197682
[junit4] 2> 85163 T195 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/]
[junit4] 2> 85166 T195 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 85167 T195 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 85167 T195 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 85168 T195 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 85169 T195 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 85170 T195 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 85176 T195 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 85177 T195 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 85178 T195 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 85179 T195 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4] 2> 85235 T195 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr
[junit4] 2> 85276 T195 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/
[junit4] 2> 85281 T195 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 85289 T205 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1
[junit4] 2> 85289 T205 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/'
[junit4] 2> 85440 T205 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 85442 T205 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 85443 T205 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 85444 T205 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 85445 T205 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 85446 T205 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 85447 T205 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 85448 T205 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 85449 T205 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/../../../dist).
[junit4] 2> 85586 T205 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 85622 T205 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 85865 T205 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 85867 T205 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 85960 T205 oass.IndexSchema.readSchema [null] Schema name=example
[junit4] 2> 87221 T205 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 87281 T205 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 87304 T205 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 87478 T205 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 87479 T205 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/
[junit4] 2> 87479 T205 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@49cda7e7
[junit4] 2> 87486 T205 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 87488 T205 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 87489 T205 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885
[junit4] 2> 87489 T205 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index/
[junit4] 2> 87490 T205 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index' doesn't exist. Creating new index...
[junit4] 2> 87491 T205 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index
[junit4] 2> 87494 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@30791901
[junit4] 2> 87495 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 87495 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: 0 msec to checkpoint
[junit4] 2> 87496 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: init: create=true
[junit4] 2> 87496 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@5e58a983
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 87497 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 87497 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 87498 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: index before flush
[junit4] 2> 87499 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 startFullFlush
[junit4] 2> 87499 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87500 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 finishFullFlush success=true
[junit4] 2> 87500 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: apply all deletes during flush
[junit4] 2> 87501 T205 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-77-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@ee107d9 minGen=9223372036854775807 packetCount=0
[junit4] 2> 87501 T205 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-77-thread-1]: now merge
[junit4] 2> 87502 T205 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-77-thread-1]: index:
[junit4] 2> 87502 T205 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-77-thread-1]: no more merges pending; now return
[junit4] 2> 87503 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: waitForMerges
[junit4] 2> 87503 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: waitForMerges done
[junit4] 2> 87505 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: now call final commit()
[junit4] 2> 87506 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: start
[junit4] 2> 87506 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: enter lock
[junit4] 2> 87507 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: now prepare
[junit4] 2> 87508 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: prepareCommit: flush
[junit4] 2> 87508 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: index before flush
[junit4] 2> 87518 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 startFullFlush
[junit4] 2> 87519 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87520 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: apply all deletes during flush
[junit4] 2> 87520 T205 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-77-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@ee107d9 minGen=9223372036854775807 packetCount=0
[junit4] 2> 87521 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 finishFullFlush success=true
[junit4] 2> 87522 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: startCommit(): start
[junit4] 2> 87523 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: startCommit index= changeCount=1
[junit4] 2> 87524 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: done all syncs: []
[junit4] 2> 87524 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: pendingCommit != null
[junit4] 2> 87525 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 87526 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 87527 T205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_1,generation=1}
[junit4] 2> 87539 T205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 87540 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: 13 msec to checkpoint
[junit4] 2> 87540 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: commit: done
[junit4] 2> 87541 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: at close:
[junit4] 2> 87555 T205 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 87556 T205 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 87557 T205 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 87558 T205 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 87559 T205 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 87588 T205 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 87591 T205 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 87607 T205 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 87609 T205 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 87619 T205 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 87622 T205 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 87627 T205 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.JsonUpdateRequestHandler
[junit4] 2> 87630 T205 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.CSVRequestHandler
[junit4] 2> 87637 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 87642 T205 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 87643 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 87644 T205 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 87646 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 87647 T205 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 87649 T205 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 87652 T205 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 87654 T205 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 87657 T205 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 87659 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 87660 T205 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 87661 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 87662 T205 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 87663 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 87665 T205 oasc.RequestHandlers.initHandlersFromConfig created /js: org.apache.solr.handler.js.JavaScriptRequestHandler
[junit4] 2> 87665 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 87667 T205 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 87667 T205 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 87669 T205 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 87691 T205 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 87697 T205 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 87708 T205 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 87725 T205 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 87726 T205 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 87731 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@30791901
[junit4] 2> 87732 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: init: load commit "segments_1"
[junit4] 2> 87733 T205 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_1,generation=1}
[junit4] 2> 87734 T205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 87734 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 87735 T205 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-77-thread-1]: 0 msec to checkpoint
[junit4] 2> 87736 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: init: create=false
[junit4] 2> 87737 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]:
[junit4] 2> dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865)
[junit4] 2> index=
[junit4] 2> version=4.5-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_45
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene45
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@7a46752d
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 87738 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: flush at getReader
[junit4] 2> 87739 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 startFullFlush
[junit4] 2> 87740 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87740 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: apply all deletes during flush
[junit4] 2> 87741 T205 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-77-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=0
[junit4] 2> 87742 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 87743 T205 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-77-thread-1]: coreLoadExecutor-77-thread-1 finishFullFlush success=true
[junit4] 2> 87744 T205 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-77-thread-1]: getReader took 6 msec
[junit4] 2> 87744 T205 oass.SolrIndexSearcher.<init> Opening Searcher@7c02dce0 main
[junit4] 2> 87745 T205 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 87746 T205 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> 87748 T205 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 87750 T205 oashc.QueryElevationComponent.inform Loading QueryElevation from: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 87790 T205 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 87790 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@7c02dce0 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@4b3ca972
[junit4] 2> 87794 T206 C20 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=3
[junit4] 2> 87795 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 87795 T206 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 87796 T206 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 87808 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c02dce0 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 87839 T205 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 87841 T195 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0
[junit4] 2> 87841 T195 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 87842 T195 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#54738
[junit4] 2> 87864 T195 oas.SolrTestCaseJ4.setUp ###Starting testAddDelete
[junit4] 2> 87875 T195 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 87971 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87972 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 87973 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87974 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: flush at getReader
[junit4] 2> 87975 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 startFullFlush
[junit4] 2> 87975 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 87976 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202: flush naked frozen global deletes
[junit4] 2> 87978 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: push deletes 1 deleted queries bytesUsed=36 delGen=2 packetCount=1 totBytesUsed=36
[junit4] 2> 87979 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 87980 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: apply all deletes during flush
[junit4] 2> 87980 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=1
[junit4] 2> 87982 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 87983 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 87983 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 finishFullFlush success=true
[junit4] 2> 87985 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: getReader took 11 msec
[junit4] 2> 87987 T202 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=*:* (-1444178671443116032)} 0 20
[junit4] 2> 88022 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@33acf5f7
[junit4] 2> 88368 T203 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[0 & 222 (1444178671601451008)]} 0 251
[junit4] 2> 88373 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 & 222 is 200
[junit4] 2> 88374 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@33acf5f7
[junit4] 2> 88382 T199 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 88383 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: start
[junit4] 2> 88383 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: enter lock
[junit4] 2> 88384 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: now prepare
[junit4] 2> 88385 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: prepareCommit: flush
[junit4] 2> 88385 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: index before flush
[junit4] 2> 88386 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: qtp1357410461-199 startFullFlush
[junit4] 2> 88387 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88387 T199 C20 oasu.LoggingInfoStream.message [DWFC][qtp1357410461-199]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_0, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 88388 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: flush postings as segment _0 numDocs=1
[junit4] 2> 88393 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: new segment has 0 deleted docs
[junit4] 2> 88394 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 88395 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: flushedFiles=[_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4] 2> 88396 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: flushed codec=Lucene45
[junit4] 2> 88418 T199 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-199]: flushed: segment=_0 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,804.778
[junit4] 2> 88419 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 88421 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: publishFlushedSegment
[junit4] 2> 88422 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
[junit4] 2> 88422 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: publish sets newSegment delGen=5 seg=_0(4.5):C1
[junit4] 2> 88423 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 88424 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: 0 msec to checkpoint
[junit4] 2> 88425 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: apply all deletes during flush
[junit4] 2> 88426 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
[junit4] 2> 88427 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: applyDeletes took 1 msec
[junit4] 2> 88427 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=6 packetCount=1
[junit4] 2> 88428 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 88429 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: qtp1357410461-199 finishFullFlush success=true
[junit4] 2> 88430 T199 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-199]: findMerges: 1 segments
[junit4] 2> 88431 T199 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-199]: seg=_0(4.5):C1 size=0.000 MB [floored]
[junit4] 2> 88432 T199 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-199]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 88433 T199 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-199]: now merge
[junit4] 2> 88434 T199 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-199]: index: _0(4.5):C1
[junit4] 2> 88434 T199 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-199]: no more merges pending; now return
[junit4] 2> 88435 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: startCommit(): start
[junit4] 2> 88436 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: startCommit index=_0(4.5):C1 changeCount=3
[junit4] 2> 88438 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: done all syncs: [_0.fnm, _0_Lucene41_0.doc, _0.fdx, _0.si, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4] 2> 88439 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: pendingCommit != null
[junit4] 2> 88440 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: wrote segments file "segments_2"
[junit4] 2> 88441 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: now checkpoint "_0(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 88442 T199 C20 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_2,generation=2}
[junit4] 2> 88443 T199 C20 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 88444 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 88445 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: delete "segments_1"
[junit4] 2> 88446 T199 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-199]: 4 msec to checkpoint
[junit4] 2> 88447 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: commit: done
[junit4] 2> 88448 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88449 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 88450 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: flush at getReader
[junit4] 2> 88451 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: qtp1357410461-199 startFullFlush
[junit4] 2> 88451 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88452 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: apply all deletes during flush
[junit4] 2> 88453 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: applyDeletes: no deletes; skipping
[junit4] 2> 88454 T199 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-199]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=6 packetCount=0
[junit4] 2> 88457 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)
[junit4] 2> 88458 T199 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-199]: qtp1357410461-199 finishFullFlush success=true
[junit4] 2> 88459 T199 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-199]: getReader took 9 msec
[junit4] 2> 88460 T199 C20 oass.SolrIndexSearcher.<init> Opening Searcher@5eae264f main
[junit4] 2> 88462 T199 C20 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 88462 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@5eae264f main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 88464 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 88473 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5eae264f main{StandardDirectoryReader(segments_2:3:nrt _0(4.5):C1)}
[junit4] 2> 88481 T199 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 99
[junit4] 2> 88492 T200 C20 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=1 status=0 QTime=2
[junit4] 2> 88506 T201 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {delete=[0 & 222 (-1444178672006201344)]} 0 3
[junit4] 2> 88517 T202 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 88519 T202 C20 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 88520 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88521 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 88522 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88523 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: flush at getReader
[junit4] 2> 88524 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 startFullFlush
[junit4] 2> 88525 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88531 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202: flush naked frozen global deletes
[junit4] 2> 88533 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=8 packetCount=1 totBytesUsed=1024
[junit4] 2> 88534 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: flush: push buffered deletes: 1 deleted terms (unique count=1) bytesUsed=1024
[junit4] 2> 88535 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: apply all deletes during flush
[junit4] 2> 88536 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: applyDeletes: infos=[_0(4.5):C1] packetCount=1
[junit4] 2> 88539 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: seg=_0(4.5):C1 segGen=6 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=1 100% deleted
[junit4] 2> 88540 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: applyDeletes took 4 msec
[junit4] 2> 88541 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: now checkpoint "_0(4.5):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 88542 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: 0 msec to checkpoint
[junit4] 2> 88542 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: drop 100% deleted segments: _0(4.5):C1/1
[junit4] 2> 88543 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 88544 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: 0 msec to checkpoint
[junit4] 2> 88545 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=1
[junit4] 2> 88546 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 88547 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 88548 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 finishFullFlush success=true
[junit4] 2> 88549 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: getReader took 26 msec
[junit4] 2> 88550 T202 C20 oass.SolrIndexSearcher.<init> Opening Searcher@1f143614 main
[junit4] 2> 88559 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1f143614 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 88560 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 88570 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f143614 main{StandardDirectoryReader(segments_2:5:nrt)}
[junit4] 2> 88573 T202 C20 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 88574 T202 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 57
[junit4] 2> 88590 T204 C20 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=2
[junit4] 2> 88643 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@79bf3519
[junit4] 2> 88907 T203 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[0 & 222 (1444178672166633472)]} 0 250
[junit4] 2> 88910 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 & 222 is 200
[junit4] 2> 88911 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@79bf3519
[junit4] 2> 88916 T200 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 88917 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: start
[junit4] 2> 88918 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: enter lock
[junit4] 2> 88918 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: now prepare
[junit4] 2> 88919 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: prepareCommit: flush
[junit4] 2> 88919 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: index before flush
[junit4] 2> 88920 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: qtp1357410461-200 startFullFlush
[junit4] 2> 88921 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88921 T200 C20 oasu.LoggingInfoStream.message [DWFC][qtp1357410461-200]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 88922 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: flush postings as segment _1 numDocs=1
[junit4] 2> 88925 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: new segment has 0 deleted docs
[junit4] 2> 88925 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 88926 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: flushedFiles=[_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 88926 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: flushed codec=Lucene45
[junit4] 2> 88928 T200 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-200]: flushed: segment=_1 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,804.778
[junit4] 2> 88929 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 88930 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: publishFlushedSegment
[junit4] 2> 88931 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
[junit4] 2> 88932 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: publish sets newSegment delGen=11 seg=_1(4.5):C1
[junit4] 2> 88933 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: now checkpoint "_1(4.5):C1" [1 segments ; isCommit = false]
[junit4] 2> 88934 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: 1 msec to checkpoint
[junit4] 2> 88935 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: apply all deletes during flush
[junit4] 2> 88936 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: applyDeletes: infos=[_1(4.5):C1] packetCount=1
[junit4] 2> 88937 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: applyDeletes took 1 msec
[junit4] 2> 88938 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=12 packetCount=1
[junit4] 2> 88938 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 88939 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: qtp1357410461-200 finishFullFlush success=true
[junit4] 2> 88940 T200 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-200]: findMerges: 1 segments
[junit4] 2> 88941 T200 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-200]: seg=_1(4.5):C1 size=0.000 MB [floored]
[junit4] 2> 88941 T200 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-200]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 88942 T200 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-200]: now merge
[junit4] 2> 88943 T200 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-200]: index: _1(4.5):C1
[junit4] 2> 88944 T200 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-200]: no more merges pending; now return
[junit4] 2> 88944 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: startCommit(): start
[junit4] 2> 88945 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: startCommit index=_1(4.5):C1 changeCount=8
[junit4] 2> 88946 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: done all syncs: [_1.fdx, _1_Lucene41_0.doc, _1.fdt, _1.si, _1_Lucene41_0.tim, _1_Lucene41_0.tip, _1.fnm]
[junit4] 2> 88947 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: pendingCommit != null
[junit4] 2> 88948 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: wrote segments file "segments_3"
[junit4] 2> 88949 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: now checkpoint "_1(4.5):C1" [1 segments ; isCommit = true]
[junit4] 2> 88950 T200 C20 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_3,generation=3}
[junit4] 2> 88951 T200 C20 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 88952 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 88953 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0.fnm"
[junit4] 2> 88954 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0_Lucene41_0.doc"
[junit4] 2> 88955 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "segments_2"
[junit4] 2> 88956 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0.fdx"
[junit4] 2> 88958 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0.si"
[junit4] 2> 88959 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0_Lucene41_0.tim"
[junit4] 2> 88959 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0.fdt"
[junit4] 2> 88960 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: delete "_0_Lucene41_0.tip"
[junit4] 2> 88961 T200 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-200]: 11 msec to checkpoint
[junit4] 2> 88961 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: commit: done
[junit4] 2> 88963 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88963 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 88964 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: flush at getReader
[junit4] 2> 88964 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: qtp1357410461-200 startFullFlush
[junit4] 2> 88965 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 88965 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: apply all deletes during flush
[junit4] 2> 88966 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: applyDeletes: no deletes; skipping
[junit4] 2> 88967 T200 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-200]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=12 packetCount=0
[junit4] 2> 88969 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)
[junit4] 2> 88969 T200 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-200]: qtp1357410461-200 finishFullFlush success=true
[junit4] 2> 88970 T200 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-200]: getReader took 6 msec
[junit4] 2> 88970 T200 C20 oass.SolrIndexSearcher.<init> Opening Searcher@236eacf1 main
[junit4] 2> 88975 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@236eacf1 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)}
[junit4] 2> 88975 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 88975 T200 C20 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 88982 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@236eacf1 main{StandardDirectoryReader(segments_3:7:nrt _1(4.5):C1)}
[junit4] 2> 88983 T200 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 67
[junit4] 2> 88993 T201 C20 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=1 status=0 QTime=1
[junit4] 2> 89012 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89013 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 89014 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89014 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: flush at getReader
[junit4] 2> 89015 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 startFullFlush
[junit4] 2> 89016 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89017 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202: flush naked frozen global deletes
[junit4] 2> 89019 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: push deletes 1 deleted queries bytesUsed=36 delGen=14 packetCount=1 totBytesUsed=36
[junit4] 2> 89019 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: flush: push buffered deletes: 1 deleted queries bytesUsed=36
[junit4] 2> 89020 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: apply all deletes during flush
[junit4] 2> 89021 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: applyDeletes: infos=[_1(4.5):C1] packetCount=1
[junit4] 2> 89026 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: seg=_1(4.5):C1 segGen=12 coalesced deletes=[CoalescedDeletes(termSets=1,queries=1)] newDelCount=1 100% deleted
[junit4] 2> 89028 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: applyDeletes took 7 msec
[junit4] 2> 89029 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: now checkpoint "_1(4.5):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 89030 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: 0 msec to checkpoint
[junit4] 2> 89031 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: drop 100% deleted segments: _1(4.5):C1/1
[junit4] 2> 89031 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 89033 T202 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-202]: 1 msec to checkpoint
[junit4] 2> 89034 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=1
[junit4] 2> 89035 T202 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-202]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89036 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: return reader version=9 reader=StandardDirectoryReader(segments_3:9:nrt)
[junit4] 2> 89036 T202 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-202]: qtp1357410461-202 finishFullFlush success=true
[junit4] 2> 89037 T202 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-202]: getReader took 23 msec
[junit4] 2> 89038 T202 C20 oass.SolrIndexSearcher.<init> Opening Searcher@4bb2668f realtime
[junit4] 2> 89039 T202 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {deleteByQuery=id:"0\ \&\ 222" (-1444178672536780800)} 0 30
[junit4] 2> 89045 T204 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89046 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: start
[junit4] 2> 89047 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: enter lock
[junit4] 2> 89047 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: now prepare
[junit4] 2> 89048 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: prepareCommit: flush
[junit4] 2> 89048 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: index before flush
[junit4] 2> 89049 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 startFullFlush
[junit4] 2> 89050 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89050 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: apply all deletes during flush
[junit4] 2> 89051 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=0
[junit4] 2> 89052 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 finishFullFlush success=true
[junit4] 2> 89052 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit(): start
[junit4] 2> 89053 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit index= changeCount=11
[junit4] 2> 89053 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: done all syncs: []
[junit4] 2> 89054 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: pendingCommit != null
[junit4] 2> 89055 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: wrote segments file "segments_4"
[junit4] 2> 89056 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 89057 T204 C20 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_4,generation=4}
[junit4] 2> 89057 T204 C20 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 89058 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 89058 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1.fdx"
[junit4] 2> 89059 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1_Lucene41_0.doc"
[junit4] 2> 89060 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: 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> 89060 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1.fdt"
[junit4] 2> 89061 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: unable to remove file "_1.fdt": java.io.IOException: MockDirectoryWrapper: file "_1.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 89062 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1.si"
[junit4] 2> 89062 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1_Lucene41_0.tim"
[junit4] 2> 89063 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: 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> 89064 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1_Lucene41_0.tip"
[junit4] 2> 89064 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_1.fnm"
[junit4] 2> 89065 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "segments_3"
[junit4] 2> 89066 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: 9 msec to checkpoint
[junit4] 2> 89066 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: done
[junit4] 2> 89067 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89067 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 89068 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89069 T204 C20 oass.SolrIndexSearcher.<init> Opening Searcher@53e66f65 main
[junit4] 2> 89071 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@53e66f65 main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 89073 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89073 T204 C20 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89080 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@53e66f65 main{StandardDirectoryReader(segments_3:9:nrt)}
[junit4] 2> 89082 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete pending file _1_Lucene41_0.doc
[junit4] 2> 89083 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 89083 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete pending file _1.fdt
[junit4] 2> 89084 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete "_1.fdt"
[junit4] 2> 89084 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete pending file _1_Lucene41_0.tim
[junit4] 2> 89084 T206 oasu.LoggingInfoStream.message [IFD][searcherExecutor-78-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 89085 T204 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 40
[junit4] 2> 89096 T199 C20 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=0 status=0 QTime=1
[junit4] 2> 89099 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@27adc5f7
[junit4] 2> 89102 T210 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@2ad1223d
[junit4] 2> 89102 T211 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@81ee8c1
[junit4] 2> 89114 T211 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@81ee8c1
[junit4] 2> 89117 T212 oascsi.ConcurrentUpdateSolrServer$Runner.run starting runner: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@d58bc22
[junit4] 2> 89131 T212 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@d58bc22
[junit4] 2> 89369 T203 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[0 & 222 (1444178672646881280), 2 & 222 (1444178672656318464)]} 0 254
[junit4] 2> 89371 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 0 & 222 is 200
[junit4] 2> 89372 T209 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@27adc5f7
[junit4] 2> 89403 T201 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {add=[1 & 222 (1444178672684630016)]} 0 253
[junit4] 2> 89406 T210 oascsi.ConcurrentUpdateSolrServer$Runner.run Status for: 1 & 222 is 200
[junit4] 2> 89407 T210 oascsi.ConcurrentUpdateSolrServer$Runner.run finished: org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrServer$Runner@2ad1223d
[junit4] 2> 89416 T204 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 89416 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: start
[junit4] 2> 89417 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: enter lock
[junit4] 2> 89417 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: now prepare
[junit4] 2> 89418 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: prepareCommit: flush
[junit4] 2> 89419 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: index before flush
[junit4] 2> 89419 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 startFullFlush
[junit4] 2> 89420 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=3 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89420 T204 C20 oasu.LoggingInfoStream.message [DWFC][qtp1357410461-204]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 2 deleted terms (unique count=2) bytesUsed=470, segment=_2, aborting=false, numDocsInRAM=3, deleteQueue=DWDQ: [ generation: 9 ]]
[junit4] 2> 89421 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: flush postings as segment _2 numDocs=3
[junit4] 2> 89432 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: new segment has 0 deleted docs
[junit4] 2> 89433 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 89433 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: flushedFiles=[_2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 89434 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: flushed codec=Lucene45
[junit4] 2> 89435 T204 C20 oasu.LoggingInfoStream.message [DWPT][qtp1357410461-204]: flushed: segment=_2 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=4,839.582
[junit4] 2> 89436 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: publishFlushedSegment seg-private deletes=null
[junit4] 2> 89437 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: publishFlushedSegment
[junit4] 2> 89442 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: push deletes 3 deleted terms (unique count=3) bytesUsed=1024 delGen=17 packetCount=1 totBytesUsed=1024
[junit4] 2> 89443 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: publish sets newSegment delGen=18 seg=_2(4.5):C3
[junit4] 2> 89443 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: now checkpoint "_2(4.5):C3" [1 segments ; isCommit = false]
[junit4] 2> 89444 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: 0 msec to checkpoint
[junit4] 2> 89445 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: apply all deletes during flush
[junit4] 2> 89445 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: applyDeletes: infos=[_2(4.5):C3] packetCount=1
[junit4] 2> 89446 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: applyDeletes took 1 msec
[junit4] 2> 89446 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=19 packetCount=1
[junit4] 2> 89447 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 89447 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 finishFullFlush success=true
[junit4] 2> 89448 T204 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-204]: findMerges: 1 segments
[junit4] 2> 89449 T204 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-204]: seg=_2(4.5):C3 size=0.000 MB [floored]
[junit4] 2> 89449 T204 C20 oasu.LoggingInfoStream.message [TMP][qtp1357410461-204]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 89450 T204 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-204]: now merge
[junit4] 2> 89450 T204 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-204]: index: _2(4.5):C3
[junit4] 2> 89452 T204 C20 oasu.LoggingInfoStream.message [CMS][qtp1357410461-204]: no more merges pending; now return
[junit4] 2> 89452 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit(): start
[junit4] 2> 89452 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit index=_2(4.5):C3 changeCount=14
[junit4] 2> 89453 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: done all syncs: [_2.si, _2_Lucene41_0.tim, _2.fdt, _2_Lucene41_0.doc, _2_Lucene41_0.tip, _2.fdx, _2.fnm]
[junit4] 2> 89454 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: pendingCommit != null
[junit4] 2> 89455 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: wrote segments file "segments_5"
[junit4] 2> 89455 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: now checkpoint "_2(4.5):C3" [1 segments ; isCommit = true]
[junit4] 2> 89456 T204 C20 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_5,generation=5}
[junit4] 2> 89456 T204 C20 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 89457 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 89458 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "segments_4"
[junit4] 2> 89458 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: 2 msec to checkpoint
[junit4] 2> 89459 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: done
[junit4] 2> 89459 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89460 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 89460 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: flush at getReader
[junit4] 2> 89461 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 startFullFlush
[junit4] 2> 89462 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 89463 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: apply all deletes during flush
[junit4] 2> 89463 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: applyDeletes: no deletes; skipping
[junit4] 2> 89464 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=19 packetCount=0
[junit4] 2> 89466 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: return reader version=11 reader=StandardDirectoryReader(segments_5:11:nrt _2(4.5):C3)
[junit4] 2> 89466 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 finishFullFlush success=true
[junit4] 2> 89467 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: getReader took 7 msec
[junit4] 2> 89467 T204 C20 oass.SolrIndexSearcher.<init> Opening Searcher@3a4346cd main
[junit4] 2> 89469 T204 C20 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 89469 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@3a4346cd main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C3)}
[junit4] 2> 89470 T206 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 89476 T206 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a4346cd main{StandardDirectoryReader(segments_5:11:nrt _2(4.5):C3)}
[junit4] 2> 89477 T204 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&wt=xml&version=2.2&softCommit=false} {commit=} 0 62
[junit4] 2> 89486 T199 C20 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=3 status=0 QTime=2
[junit4] 2> 89496 T200 C20 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=xml&version=2.2} {delete=[0 & 222 (-1444178673044291584), 1 & 222 (-1444178673045340160), 2 & 222 (-1444178673046388736)]} 0 2
[junit4] 2> 104497 T208 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 104497 T208 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 104497 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 104498 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 104498 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 104498 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: flush at getReader
[junit4] 2> 104499 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: commitScheduler-80-thread-1 startFullFlush
[junit4] 2> 104499 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 104499 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: commitScheduler-80-thread-1: flush naked frozen global deletes
[junit4] 2> 104499 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: push deletes 3 deleted terms (unique count=3) bytesUsed=1024 delGen=21 packetCount=1 totBytesUsed=1024
[junit4] 2> 104500 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: flush: push buffered deletes: 3 deleted terms (unique count=3) bytesUsed=1024
[junit4] 2> 104500 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: apply all deletes during flush
[junit4] 2> 104500 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: applyDeletes: infos=[_2(4.5):C3] packetCount=1
[junit4] 2> 104501 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: seg=_2(4.5):C3 segGen=19 coalesced deletes=[CoalescedDeletes(termSets=1,queries=0)] newDelCount=3 100% deleted
[junit4] 2> 104502 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: applyDeletes took 2 msec
[junit4] 2> 104502 T208 oasu.LoggingInfoStream.message [IFD][commitScheduler-80-thread-1]: now checkpoint "_2(4.5):C3/3" [1 segments ; isCommit = false]
[junit4] 2> 104502 T208 oasu.LoggingInfoStream.message [IFD][commitScheduler-80-thread-1]: 0 msec to checkpoint
[junit4] 2> 104502 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: drop 100% deleted segments: _2(4.5):C3/3
[junit4] 2> 104503 T208 oasu.LoggingInfoStream.message [IFD][commitScheduler-80-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 104503 T208 oasu.LoggingInfoStream.message [IFD][commitScheduler-80-thread-1]: 0 msec to checkpoint
[junit4] 2> 104503 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=1
[junit4] 2> 104504 T208 oasu.LoggingInfoStream.message [BD][commitScheduler-80-thread-1]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 104504 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: return reader version=13 reader=StandardDirectoryReader(segments_5:13:nrt)
[junit4] 2> 104504 T208 oasu.LoggingInfoStream.message [DW][commitScheduler-80-thread-1]: commitScheduler-80-thread-1 finishFullFlush success=true
[junit4] 2> 104504 T208 oasu.LoggingInfoStream.message [IW][commitScheduler-80-thread-1]: getReader took 6 msec
[junit4] 2> 104505 T208 oass.SolrIndexSearcher.<init> Opening Searcher@72be8e1 realtime
[junit4] 2> 104506 T208 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 289843 T204 C20 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 289845 T195 oas.SolrTestCaseJ4.tearDown ###Ending testAddDelete
[junit4] 2> 289845 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: start
[junit4] 2> 289849 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: enter lock
[junit4] 2> 289860 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: now prepare
[junit4] 2> 289861 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: prepareCommit: flush
[junit4] 2> 289863 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: index before flush
[junit4] 2> 289864 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 startFullFlush
[junit4] 2> 289866 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 289867 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: apply all deletes during flush
[junit4] 2> 289869 T204 C20 oasu.LoggingInfoStream.message [BD][qtp1357410461-204]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=9223372036854775807 packetCount=0
[junit4] 2> 289870 T204 C20 oasu.LoggingInfoStream.message [DW][qtp1357410461-204]: qtp1357410461-204 finishFullFlush success=true
[junit4] 2> 289873 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit(): start
[junit4] 2> 289874 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: startCommit index= changeCount=17
[junit4] 2> 289875 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: done all syncs: []
[junit4] 2> 289875 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: pendingCommit != null
[junit4] 2> 289876 T204 C20 oasu.LoggingInfoStream.message [IW][qtp1357410461-204]: commit: wrote segments file "segments_6"
[junit4] 2> 289877 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 289877 T204 C20 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_5,generation=5}
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5ffc6345 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e7c8865),segFN=segments_6,generation=6}
[junit4] 2> 289878 T204 C20 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4] 2> 289878 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: deleteCommits: now decRef commit "segments_5"
[junit4] 2> 289879 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_2.si"
[junit4] 2> 289879 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_2_Lucene41_0.tim"
[junit4] 2> 289880 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: unable to remove file "_2_Lucene41_0.tim": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.tim" is still open: cannot delete; Will re-try later.
[junit4] 2> 289880 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_2.fdt"
[junit4] 2> 289881 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: unable to remove file "_2.fdt": java.io.IOException: MockDirectoryWrapper: file "_2.fdt" is still open: cannot delete; Will re-try later.
[junit4] 2> 289882 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_2_Lucene41_0.doc"
[junit4] 2> 289882 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: unable to remove file "_2_Lucene41_0.doc": java.io.IOException: MockDirectoryWrapper: file "_2_Lucene41_0.doc" is still open: cannot delete; Will re-try later.
[junit4] 2> 289883 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp1357410461-204]: delete "_2_Lucene41_0.tip"
[junit4] 2> 289883 T204 C20 oasu.LoggingInfoStream.message [IFD][qtp135741
[...truncated too long message...]
],commit=} 0 253
[junit4] 2> 313165 T203 C23 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&wt=xml&version=2.2} hits=5 status=0 QTime=1
[junit4] 2> 313181 T195 oas.SolrTestCaseJ4.tearDown ###Ending testMultiContentStreamRequest
[junit4] 2> 313209 T195 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1346197682
[junit4] 2> 313214 T195 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4b3ca972
[junit4] 2> 313502 T195 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=69,autocommit maxTime=15000ms,autocommits=1,soft autocommits=3,optimizes=8,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=1,cumulative_adds=158,cumulative_deletesById=5,cumulative_deletesByQuery=28,cumulative_errors=1}
[junit4] 2> 313506 T195 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 313506 T195 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 313507 T195 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 313511 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: now flush at close waitForMerges=true
[junit4] 2> 313512 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 313513 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: index before flush _1m(4.5):C5
[junit4] 2> 313514 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker startFullFlush
[junit4] 2> 313515 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 313517 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker finishFullFlush success=true
[junit4] 2> 313519 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: apply all deletes during flush
[junit4] 2> 313520 T195 C23 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 313520 T195 C23 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=292 packetCount=0
[junit4] 2> 313521 T195 C23 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: now merge
[junit4] 2> 313522 T195 C23 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: index: _1m(4.5):C5
[junit4] 2> 313523 T195 C23 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: no more merges pending; now return
[junit4] 2> 313524 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: waitForMerges
[junit4] 2> 313525 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: waitForMerges done
[junit4] 2> 313532 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: now call final commit()
[junit4] 2> 313534 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: commit: start
[junit4] 2> 313535 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: commit: enter lock
[junit4] 2> 313560 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: commit: now prepare
[junit4] 2> 313562 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: prepareCommit: flush
[junit4] 2> 313564 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: index before flush _1m(4.5):C5
[junit4] 2> 313567 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker startFullFlush
[junit4] 2> 313570 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 313573 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: apply all deletes during flush
[junit4] 2> 313578 T195 C23 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 313581 T195 C23 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@27b71c12 minGen=292 packetCount=0
[junit4] 2> 313586 T195 C23 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker finishFullFlush success=true
[junit4] 2> 313587 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: startCommit(): start
[junit4] 2> 313588 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: skip startCommit(): no changes pending
[junit4] 2> 313589 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 313590 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: commit: done
[junit4] 2> 313591 T195 C23 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleStreamingTest-seed#[7E9D2317BE52487B]-worker]: at close: _1m(4.5):C5
[junit4] 2> 313600 T195 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 313603 T195 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 313604 T195 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index;done=false>>]
[junit4] 2> 313606 T195 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885/index
[junit4] 2> 313608 T195 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885;done=false>>]
[junit4] 2> 313610 T195 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-solrj/test/J0/solrtest-SolrExampleStreamingTest-1377276103885
[junit4] 2> 313613 T195 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 313669 T195 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Asserting, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=cs, timezone=America/Fort_Wayne
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Apple Inc. 1.6.0_51 (64-bit)/cpus=2,threads=10,free=30046088,total=188416000
[junit4] 2> NOTE: All tests run in this JVM: [LargeVolumeBinaryJettyTest, ContentStreamTest, CloudSolrServerTest, TestDocumentObjectBinder, SolrParamTest, SolrPingTest, TestXMLEscaping, LargeVolumeJettyTest, SolrExampleStreamingTest]
[junit4] Completed in 229.23s, 27 tests, 1 error <<< FAILURES!
[...truncated 117 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:395: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:375: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:194: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:450: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 46 suites, 272 tests, 1 error
Total time: 99 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0 -XX:-UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 738 -
Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/738/
Java: 64bit/jdk1.6.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
collection already exists: awholynewcollection_0
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: collection already exists: awholynewcollection_0
at __randomizedtesting.SeedInfo.seed([51DE843806B20F8B:D0380A2071ED6FB7]: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:264)
at org.apache.solr.client.solrj.impl.CloudSolrServer.request(CloudSolrServer.java:318)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1571)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1585)
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:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:680)
Build Log:
[...truncated 9211 lines...]
[junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4] 2> 1204449 T3012 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_j/ho
[junit4] 2> 1204455 T3012 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-CollectionsAPIDistributedZkTest-1377301725651
[junit4] 2> 1204457 T3012 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1204458 T3013 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1204560 T3012 oasc.ZkTestServer.run start zk server on port:52671
[junit4] 2> 1204564 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1204573 T3019 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68d11de name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1204574 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1204574 T3012 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1204591 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1204596 T3021 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f7ef7a5 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1204596 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1204597 T3012 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 1204609 T3012 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 1204619 T3012 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 1204629 T3012 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 1204640 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 1204640 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 1204657 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 1204658 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 1204669 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1204670 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1204682 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 1204682 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 1204694 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 1204694 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 1204706 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 1204707 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 1204718 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 1204718 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 1204732 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1204734 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1204746 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 1204747 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 1204758 T3012 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 1204759 T3012 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 1205165 T3012 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1205182 T3012 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52674
[junit4] 2> 1205183 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1205184 T3012 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1205184 T3012 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966
[junit4] 2> 1205185 T3012 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/'
[junit4] 2> 1205229 T3012 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/solr.xml
[junit4] 2> 1205308 T3012 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1205310 T3012 oasc.CoreContainer.<init> New CoreContainer 196060392
[junit4] 2> 1205310 T3012 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/]
[junit4] 2> 1205313 T3012 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1205314 T3012 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1205315 T3012 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1205315 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1205316 T3012 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1205317 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1205317 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1205318 T3012 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1205332 T3012 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1205333 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1205365 T3012 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52671/solr
[junit4] 2> 1205366 T3012 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1205368 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1205373 T3032 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2730520e name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1205374 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1205378 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1205402 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1205406 T3034 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49f47e87 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1205407 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1205411 T3012 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1205424 T3012 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1205437 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1205445 T3012 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52674__j%2Fho
[junit4] 2> 1205447 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52674__j%2Fho
[junit4] 2> 1205459 T3012 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1205477 T3012 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1205487 T3012 oasc.Overseer.start Overseer (id=90262845892853763-127.0.0.1:52674__j%2Fho-n_0000000000) starting
[junit4] 2> 1205503 T3012 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1205522 T3036 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1205525 T3012 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1205536 T3012 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1205543 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1205556 T3035 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1205559 T3012 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966
[junit4] 2> 1205790 T3012 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/conf/
[junit4] 2> 1205805 T3012 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1205808 T3012 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1205808 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1205809 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1205848 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4] 2> 1205850 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1205856 T3039 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20116de4 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1205856 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1205861 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1205874 T3012 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4] 2> 1206416 T3012 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1206421 T3012 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52678
[junit4] 2> 1206425 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1206426 T3012 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1206427 T3012 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069
[junit4] 2> 1206428 T3012 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/'
[junit4] 2> 1206477 T3012 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/solr.xml
[junit4] 2> 1206554 T3012 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1206555 T3012 oasc.CoreContainer.<init> New CoreContainer 1448803780
[junit4] 2> 1206556 T3012 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/]
[junit4] 2> 1206558 T3012 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1206559 T3012 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1206559 T3012 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1206560 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1206560 T3012 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1206561 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1206562 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1206562 T3012 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1206563 T3012 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1206564 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1206602 T3012 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52671/solr
[junit4] 2> 1206603 T3012 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1206605 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1206609 T3050 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6fca7b26 name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1206610 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1206615 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1206650 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1206655 T3052 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@421c996c name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1206656 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1206690 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1207704 T3012 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52678__j%2Fho
[junit4] 2> 1207708 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52678__j%2Fho
[junit4] 2> 1207720 T3034 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1207720 T3039 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1207723 T3052 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1207740 T3012 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069
[junit4] 2> 1207961 T3012 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/conf/
[junit4] 2> 1207976 T3012 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1207978 T3012 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1207979 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1207980 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1208569 T3012 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1208610 T3012 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52681
[junit4] 2> 1208616 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1208617 T3012 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1208618 T3012 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224
[junit4] 2> 1208619 T3012 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/'
[junit4] 2> 1208710 T3012 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/solr.xml
[junit4] 2> 1208820 T3012 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1208822 T3012 oasc.CoreContainer.<init> New CoreContainer 644156900
[junit4] 2> 1208823 T3012 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/]
[junit4] 2> 1208826 T3012 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1208827 T3012 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1208828 T3012 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1208829 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1208830 T3012 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1208831 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1208832 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1208833 T3012 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1208834 T3012 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1208835 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1208892 T3012 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52671/solr
[junit4] 2> 1208893 T3012 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1208896 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1208903 T3064 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3473076d name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1208904 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1208911 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1208956 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1208963 T3066 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b805606 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1208964 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1208989 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1210008 T3012 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52681__j%2Fho
[junit4] 2> 1210014 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52681__j%2Fho
[junit4] 2> 1210031 T3052 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1210034 T3066 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1210036 T3034 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1210038 T3039 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 1210055 T3012 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224
[junit4] 2> 1210268 T3012 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/conf/
[junit4] 2> 1210274 T3012 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1210275 T3012 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1210276 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1210276 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1210768 T3012 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1210773 T3012 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52684
[junit4] 2> 1210778 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1210779 T3012 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1210779 T3012 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501
[junit4] 2> 1210780 T3012 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/'
[junit4] 2> 1210826 T3012 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/solr.xml
[junit4] 2> 1210938 T3012 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1210941 T3012 oasc.CoreContainer.<init> New CoreContainer 991713538
[junit4] 2> 1210942 T3012 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/]
[junit4] 2> 1210945 T3012 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1210946 T3012 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1210947 T3012 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1210948 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1210949 T3012 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1210950 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1210951 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1210952 T3012 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1210953 T3012 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1210954 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1211004 T3012 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52671/solr
[junit4] 2> 1211006 T3012 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1211008 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1211013 T3078 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4217b09f name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1211014 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1211019 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1211063 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1211068 T3080 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7dd002f7 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1211069 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1211087 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1212105 T3012 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52684__j%2Fho
[junit4] 2> 1212109 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52684__j%2Fho
[junit4] 2> 1212121 T3034 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1212123 T3066 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1212125 T3052 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1212126 T3080 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1212127 T3039 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 1212143 T3012 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501
[junit4] 2> 1212275 T3012 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/conf/
[junit4] 2> 1212285 T3012 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1212287 T3012 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1212288 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1212289 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1212756 T3012 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 1212763 T3012 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52687
[junit4] 2> 1212765 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 1212766 T3012 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 1212767 T3012 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520
[junit4] 2> 1212767 T3012 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/'
[junit4] 2> 1212824 T3012 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/solr.xml
[junit4] 2> 1212905 T3012 oasc.ConfigSolrXml.<init> Config-defined core root directory:
[junit4] 2> 1212906 T3012 oasc.CoreContainer.<init> New CoreContainer 1041203308
[junit4] 2> 1212906 T3012 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/]
[junit4] 2> 1212908 T3012 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4] 2> 1212908 T3012 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 1212909 T3012 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 1212910 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 1212910 T3012 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 1212911 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 1212913 T3012 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 1212913 T3012 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 1212914 T3012 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 1212915 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4] 2> 1212951 T3012 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:52671/solr
[junit4] 2> 1212952 T3012 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 1212954 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1212959 T3092 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bb85248 name:ZooKeeperConnection Watcher:127.0.0.1:52671 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1212960 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1212967 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4] 2> 1212999 T3012 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1213004 T3094 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f4ec2e4 name:ZooKeeperConnection Watcher:127.0.0.1:52671/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1213005 T3012 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1213041 T3012 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1214058 T3012 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52687__j%2Fho
[junit4] 2> 1214062 T3012 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52687__j%2Fho
[junit4] 2> 1214078 T3052 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214078 T3039 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214079 T3066 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214080 T3080 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214080 T3094 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214081 T3034 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4] 2> 1214097 T3012 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520
[junit4] 2> 1214229 T3012 oasc.CorePropertiesLocator.discoverUnder Found core conf in /Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/conf/
[junit4] 2> 1214237 T3012 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 1214238 T3012 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 1214238 T3012 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 1214239 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1214271 T3012 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4] 2> 1214300 T3043 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&name=nodes_used_collection&replicationFactor=2&action=CREATE&wt=javabin&version=2
[junit4] 2> 1214306 T3034 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1214313 T3036 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> 1214313 T3036 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> 1214660 T3035 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1214662 T3035 oasc.Overseer$ClusterStateUpdater.buildCollection building a new collection: nodes_used_collection
[junit4] 2> 1214662 T3035 oasc.Overseer$ClusterStateUpdater.createCollection Create collection nodes_used_collection with shards [shard1, shard2]
[junit4] 2> 1214676 T3080 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> 1214677 T3052 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> 1214677 T3034 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> 1214677 T3066 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> 1214678 T3039 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> 1214679 T3094 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> 1214732 T3036 oasc.OverseerCollectionProcessor.createCollection going to create cores replicas shardNames [shard1, shard2] , repFactor : 2
[junit4] 2> 1214733 T3036 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:52678__j%2Fho
[junit4] 2> 1214734 T3036 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:52674__j%2Fho
[junit4] 2> 1214734 T3036 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:52681__j%2Fho
[junit4] 2> 1214739 T3036 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:52684__j%2Fho
[junit4] 2> 1214749 T3045 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica1 state=down
[junit4] 2> 1214750 T3060 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica1 state=down
[junit4] 2> 1214752 T3030 oasc.ZkController.publish publishing core=nodes_used_collection_shard1_replica2 state=down
[junit4] 2> 1214752 T3074 oasc.ZkController.publish publishing core=nodes_used_collection_shard2_replica2 state=down
[junit4] 2> 1214756 T3060 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1214757 T3030 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1214758 T3045 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1214758 T3074 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 1216212 T3035 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1216214 T3035 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":"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:52681__j%2Fho",
[junit4] 2> "base_url":"http://127.0.0.1:52681/_j/ho"}
[junit4] 2> 1216227 T3035 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":"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:52674__j%2Fho",
[junit4] 2> "base_url":"http://127.0.0.1:52674/_j/ho"}
[junit4] 2> 1216240 T3035 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":"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:52684__j%2Fho",
[junit4] 2> "base_url":"http://127.0.0.1:52684/_j/ho"}
[junit4] 2> 1216253 T3035 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":"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:52678__j%2Fho",
[junit4] 2> "base_url":"http://127.0.0.1:52678/_j/ho"}
[junit4] 2> 1216267 T3039 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> 1216267 T3034 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> 1216268 T3094 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> 1216267 T3052 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> 1216270 T3080 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> 1216273 T3066 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> 1216759 T3060 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard2_replica1
[junit4] 2> 1216759 T3030 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard1_replica2
[junit4] 2> 1216762 T3060 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica1' using instanceDir: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1
[junit4] 2> 1216762 T3060 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1216759 T3045 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard1_replica1
[junit4] 2> 1216763 T3030 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica2' using instanceDir: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2
[junit4] 2> 1216763 T3030 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1216765 T3074 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for nodes_used_collection_shard2_replica2
[junit4] 2> 1216765 T3045 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard1_replica1' using instanceDir: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1
[junit4] 2> 1216766 T3045 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1216766 T3074 oasc.CoreContainer.create Creating SolrCore 'nodes_used_collection_shard2_replica2' using instanceDir: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2
[junit4] 2> 1216767 T3074 oasc.ZkController.createCollectionZkNode Check for collection zkNode:nodes_used_collection
[junit4] 2> 1216769 T3030 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1216770 T3030 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1216770 T3060 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1216771 T3060 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1216772 T3045 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1216773 T3045 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1216770 T3074 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:nodes_used_collection
[junit4] 2> 1216774 T3074 oasc.ZkController.getConfName Looking for collection configName
[junit4] 2> 1216780 T3074 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1216781 T3074 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1216782 T3030 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1216783 T3030 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1216783 T3060 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1216784 T3060 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1216786 T3045 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4] 2> 1216786 T3045 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection
[junit4] 2> 1216798 T3074 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1216802 T3060 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1216803 T3030 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1216829 T3060 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/'
[junit4] 2> 1216831 T3045 oasc.ZkController.readConfigName Load collection config from:/collections/nodes_used_collection
[junit4] 2> 1216833 T3074 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/'
[junit4] 2> 1216837 T3030 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/'
[junit4] 2> 1216839 T3045 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/'
[junit4] 2> 1217001 T3060 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 1217090 T3074 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 1217118 T3045 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 1217189 T3030 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
[junit4] 2> 1217204 T3060 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1217227 T3060 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1217264 T3060 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1217320 T3074 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1217352 T3074 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1217385 T3074 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1217397 T3045 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1217403 T3045 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1217439 T3030 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1217442 T3045 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1217445 T3030 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 1217486 T3030 oass.IndexSchema.readSchema [null] Schema name=test
[junit4] 2> 1219470 T3060 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219470 T3060 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219472 T3060 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1219512 T3060 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1219531 T3060 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1219668 T3060 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219671 T3074 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219671 T3074 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219673 T3074 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1219677 T3060 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219686 T3060 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1219688 T3074 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1219693 T3060 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1219694 T3060 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1219695 T3060 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1219698 T3074 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1219704 T3060 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1219705 T3060 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1219706 T3060 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1219707 T3060 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica1] Opening new SolrCore at ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/, dataDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/data/
[junit4] 2> 1219707 T3060 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2942da
[junit4] 2> 1219722 T3060 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/data
[junit4] 2> 1219723 T3060 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/data/index/
[junit4] 2> 1219723 T3060 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica1] Solr index directory './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/data/index' doesn't exist. Creating new index...
[junit4] 2> 1219728 T3060 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty2-1377301729224/nodes_used_collection_shard2_replica1/data/index
[junit4] 2> 1219728 T3060 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=30, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.24458090552923117]
[junit4] 2> 1219729 T3060 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@103b40a6 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14970fd4),segFN=segments_1,generation=1}
[junit4] 2> 1219730 T3060 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1219739 T3060 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1219740 T3060 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1219740 T3060 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1219741 T3060 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1219742 T3060 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1219742 T3060 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1219744 T3060 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1219745 T3060 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1219750 T3060 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1219752 T3060 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1219779 T3060 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1219780 T3060 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1219781 T3060 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1219782 T3060 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1219783 T3060 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1219777 T3045 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219790 T3045 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219793 T3045 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1219796 T3060 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1219813 T3045 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1219822 T3030 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219823 T3030 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4] 2> 1219825 T3030 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4] 2> 1219825 T3060 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1219833 T3060 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1219853 T3045 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1219855 T3060 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@42e16ded
[junit4] 2> 1219859 T3060 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@103b40a6 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14970fd4),segFN=segments_1,generation=1}
[junit4] 2> 1219860 T3060 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1219861 T3060 oass.SolrIndexSearcher.<init> Opening Searcher@3e0cf9ee main
[junit4] 2> 1219865 T3074 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219866 T3030 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 1219875 T3100 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica1] Registered new searcher Searcher@3e0cf9ee main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1219880 T3030 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 1219883 T3060 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica1
[junit4] 2> 1219884 T3060 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica1 address:http://127.0.0.1:52681/_j/ho collection:nodes_used_collection shard:shard2
[junit4] 2> 1219885 T3060 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1219884 T3074 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219897 T3074 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1219909 T3074 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1219911 T3074 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1219911 T3074 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1219923 T3074 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1219924 T3074 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1219926 T3074 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1219927 T3074 oasc.SolrCore.<init> [nodes_used_collection_shard2_replica2] Opening new SolrCore at ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/, dataDir=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/data/
[junit4] 2> 1219928 T3074 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2942da
[junit4] 2> 1219931 T3074 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/data
[junit4] 2> 1219931 T3074 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/data/index/
[junit4] 2> 1219932 T3074 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard2_replica2] Solr index directory './org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/data/index' doesn't exist. Creating new index...
[junit4] 2> 1219934 T3074 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty3-1377301731501/nodes_used_collection_shard2_replica2/data/index
[junit4] 2> 1219935 T3074 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=30, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.24458090552923117]
[junit4] 2> 1219940 T3074 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71144fe4 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@715267ec),segFN=segments_1,generation=1}
[junit4] 2> 1219940 T3074 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1219950 T3074 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1219951 T3074 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1219952 T3074 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1219954 T3074 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1219955 T3060 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard2/election
[junit4] 2> 1219956 T3045 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219957 T3074 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1219961 T3074 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1219962 T3074 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1219964 T3074 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1219965 T3074 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1219967 T3074 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1219968 T3074 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1219968 T3074 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1219969 T3074 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1219970 T3045 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1219970 T3074 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1219972 T3074 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1219976 T3074 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1220006 T3045 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1220012 T3074 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1220012 T3074 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1220015 T3074 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@5a3157c4
[junit4] 2> 1220018 T3074 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71144fe4 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@715267ec),segFN=segments_1,generation=1}
[junit4] 2> 1220019 T3074 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1220020 T3074 oass.SolrIndexSearcher.<init> Opening Searcher@1f5cec5a main
[junit4] 2> 1220025 T3045 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1220027 T3045 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1220028 T3045 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1220033 T3101 oasc.SolrCore.registerSearcher [nodes_used_collection_shard2_replica2] Registered new searcher Searcher@1f5cec5a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1220035 T3045 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1220035 T3045 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1220036 T3045 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1220037 T3045 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica1] Opening new SolrCore at ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/, dataDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/data/
[junit4] 2> 1220038 T3045 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2942da
[junit4] 2> 1220039 T3074 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard2_replica2
[junit4] 2> 1220040 T3074 oasc.ZkController.register Register replica - core:nodes_used_collection_shard2_replica2 address:http://127.0.0.1:52684/_j/ho collection:nodes_used_collection shard:shard2
[junit4] 2> 1220040 T3074 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1220037 T3030 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1220040 T3045 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/data
[junit4] 2> 1220042 T3045 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/data/index/
[junit4] 2> 1220042 T3045 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica1] Solr index directory '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/data/index' doesn't exist. Creating new index...
[junit4] 2> 1220042 T3060 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 1220044 T3045 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty1-1377301727069/nodes_used_collection_shard1_replica1/data/index
[junit4] 2> 1220045 T3045 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=30, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.24458090552923117]
[junit4] 2> 1220046 T3045 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3bcf0b lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@37e94da2),segFN=segments_1,generation=1}
[junit4] 2> 1220047 T3045 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1220058 T3030 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 1220059 T3045 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1220060 T3045 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1220060 T3045 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1220064 T3045 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1220064 T3045 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1220065 T3045 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1220066 T3045 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1220066 T3045 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1220067 T3045 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1220068 T3045 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1220070 T3045 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1220070 T3045 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1220071 T3045 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1220072 T3045 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1220073 T3045 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1220083 T3045 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1220087 T3060 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Waiting until we see more replicas up for shard shard2: total=2 found=1 timeoutin=179994
[junit4] 2> 1220092 T3030 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1220093 T3045 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1220094 T3045 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1220095 T3045 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@3a2b4f2f
[junit4] 2> 1220096 T3045 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c3bcf0b lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@37e94da2),segFN=segments_1,generation=1}
[junit4] 2> 1220097 T3045 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1220097 T3030 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1220099 T3030 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1220099 T3030 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4] 2> 1220098 T3045 oass.SolrIndexSearcher.<init> Opening Searcher@429568e8 main
[junit4] 2> 1220111 T3102 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica1] Registered new searcher Searcher@429568e8 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1220115 T3045 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica1
[junit4] 2> 1220116 T3045 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica1 address:http://127.0.0.1:52678/_j/ho collection:nodes_used_collection shard:shard1
[junit4] 2> 1220116 T3045 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
[junit4] 2> 1220120 T3030 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4] 2> 1220121 T3030 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4] 2> 1220121 T3030 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 1220138 T3030 oasc.SolrCore.<init> [nodes_used_collection_shard1_replica2] Opening new SolrCore at ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/, dataDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/data/
[junit4] 2> 1220139 T3030 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2942da
[junit4] 2> 1220141 T3030 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/data
[junit4] 2> 1220141 T3030 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/data/index/
[junit4] 2> 1220142 T3030 oasc.SolrCore.initIndex WARN [nodes_used_collection_shard1_replica2] Solr index directory '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/data/index' doesn't exist. Creating new index...
[junit4] 2> 1220143 T3030 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-controljetty-1377301725966/nodes_used_collection_shard1_replica2/data/index
[junit4] 2> 1220144 T3030 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=30, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.24458090552923117]
[junit4] 2> 1220147 T3030 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20721767 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1b942aca),segFN=segments_1,generation=1}
[junit4] 2> 1220147 T3030 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1220154 T3030 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1220155 T3030 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1220156 T3030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1220156 T3030 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1220157 T3030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1220157 T3030 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1220158 T3030 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1220159 T3030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1220159 T3030 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 1220160 T3030 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 1220162 T3030 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 1220162 T3030 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 1220163 T3030 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 1220164 T3030 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 1220165 T3030 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 1220165 T3045 oascc.SolrZkClient.makePath makePath: /collections/nodes_used_collection/leader_elect/shard1/election
[junit4] 2> 1220169 T3030 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 1220176 T3030 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 1220177 T3030 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 1220178 T3030 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@3e64b7ab
[junit4] 2> 1220179 T3030 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20721767 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1b942aca),segFN=segments_1,generation=1}
[junit4] 2> 1220180 T3030 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 1220181 T3030 oass.SolrIndexSearcher.<init> Opening Searcher@63693f6a main
[junit4] 2> 1220190 T3103 oasc.SolrCore.registerSearcher [nodes_used_collection_shard1_replica2] Registered new searcher Searcher@63693f6a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 1220194 T3045 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 1220195 T3030 oasc.CoreContainer.registerCore registering core: nodes_used_collection_shard1_replica2
[junit4] 2> 1220195 T3030 oasc.ZkController.register Register replica - core:nodes_used_collection_shard1_replica2 address:http://127.0.0.1:52674/_j/ho collection:nodes_used_collection shard:shard1
[junit4] 2> 1220196
[...truncated too long message...]
lectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard4_replica5/data
[junit4] 2> 1330323 T3012 oasc.SolrCore.close [awholynewcollection_0_shard3_replica5] CLOSING SolrCore org.apache.solr.core.SolrCore@8111f5b
[junit4] 2> 1330347 T3384 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1330351 T3385 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1330351 T3012 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> 1330352 T3012 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 1330353 T3012 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 1330353 T3012 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 1330355 T3012 oasc.SolrCore.closeSearcher [awholynewcollection_0_shard3_replica5] Closing main searcher on request.
[junit4] 2> 1330355 T3012 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 1330356 T3012 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data/index;done=false>>]
[junit4] 2> 1330357 T3012 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data/index
[junit4] 2> 1330357 T3012 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data;done=false>>]
[junit4] 2> 1330358 T3012 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.CollectionsAPIDistributedZkTest-jetty4-1377301733520/awholynewcollection_0_shard3_replica5/data
[junit4] 2> 1330381 T3012 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/_j/ho,null}
[junit4] 2> 1330443 T3012 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4] 2> 1330446 T3012 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:52671 52671
[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=51DE843806B20F8B -Dtests.slow=true -Dtests.locale=tr_TR -Dtests.timezone=Atlantic/Azores -Dtests.file.encoding=ISO-8859-1
[junit4] ERROR 126s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: collection already exists: awholynewcollection_0
[junit4] > at __randomizedtesting.SeedInfo.seed([51DE843806B20F8B:D0380A2071ED6FB7]: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:264)
[junit4] > at org.apache.solr.client.solrj.impl.CloudSolrServer.request(CloudSolrServer.java:318)
[junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1571)
[junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1585)
[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:680)
[junit4] 2> 1330559 T3012 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> 126117 T3011 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4] 2> 1331669 T3094 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1331669 T3094 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> 1331669 T3094 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=300), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=300)), sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=tr_TR, timezone=Atlantic/Azores
[junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Apple Inc. 1.6.0_51 (64-bit)/cpus=2,threads=2,free=94325784,total=532545536
[junit4] 2> NOTE: All tests run in this JVM: [TestSweetSpotSimilarityFactory, TestAddFieldRealTimeGet, SpellCheckCollatorTest, CurrencyFieldXmlFileTest, UpdateRequestProcessorFactoryTest, StressHdfsTest, DocValuesMissingTest, TestSolrIndexConfig, TestCoreContainer, TestSort, XsltUpdateRequestHandlerTest, TestRandomDVFaceting, TestSolrXml, TestBadConfig, TestLMJelinekMercerSimilarityFactory, TestCharFilters, HighlighterTest, DeleteShardTest, TestIndexSearcher, TestGroupingSearch, TestFunctionQuery, TestQuerySenderListener, RequiredFieldsTest, TestAtomicUpdateErrorCases, URLClassifyProcessorTest, ReturnFieldsTest, TestSolr4Spatial, HdfsChaosMonkeySafeLeaderTest, TestImplicitCoreProperties, BasicZkTest, DirectSolrConnectionTest, SimpleFacetsTest, TestLazyCores, UpdateParamsTest, TestStressVersions, TestPhraseSuggestions, TestSearchPerf, TestSolrCoreProperties, PreAnalyzedFieldTest, SimplePostToolTest, DirectSolrSpellCheckerTest, TestReversedWildcardFilterFactory, TestSolrDeletionPolicy1, CoreAdminCreateDiscoverTest, BadComponentTest, DistributedTermsComponentTest, HdfsBasicDistributedZk2Test, SolrInfoMBeanTest, RegexBoostProcessorTest, DOMUtilTest, SpellPossibilityIteratorTest, SuggesterTest, ScriptEngineTest, ChaosMonkeyNothingIsSafeTest, CacheHeaderTest, OverseerTest, PathHierarchyTokenizerFactoryTest, TestRTGBase, SliceStateTest, TestReloadAndDeleteDocs, TestFoldingMultitermQuery, SchemaVersionSpecificBehaviorTest, TestArbitraryIndexDir, DocumentAnalysisRequestHandlerTest, MBeansHandlerTest, TestReplicationHandler, TestUpdate, TestRandomFaceting, TestPartialUpdateDeduplication, JSONWriterTest, TestCopyFieldCollectionResource, TestSchemaVersionResource, StatsComponentTest, FieldMutatingUpdateProcessorTest, TestWordDelimiterFilterFactory, TestFieldResource, ShowFileRequestHandlerTest, DefaultValueUpdateProcessorTest, TestDistributedGrouping, BJQParserTest, TestMultiCoreConfBootstrap, StatelessScriptUpdateProcessorFactoryTest, OutputWriterTest, TestNoOpRegenerator, ZkControllerTest, TestSolrQueryParserResource, DistanceFunctionTest, TestConfig, ShardSplitTest, PluginInfoTest, SolrIndexSplitterTest, DistributedQueryElevationComponentTest, HdfsCollectionsAPIDistributedZkTest, TestHashPartitioner, TestSchemaSimilarityResource, HighlighterConfigTest, TestAnalyzedSuggestions, IndexSchemaTest, FieldAnalysisRequestHandlerTest, ConvertedLegacyTest, FileBasedSpellCheckerTest, LeaderElectionTest, NumericFieldsTest, TestPseudoReturnFields, TestShardHandlerFactory, RequestHandlersTest, HardAutoCommitTest, ExternalFileFieldSortTest, HdfsBasicDistributedZkTest, EchoParamsTest, SpellCheckComponentTest, TestSolrQueryParser, TestSchemaResource, BadIndexSchemaTest, TestJoin, TestDefaultSearchFieldResource, AddSchemaFieldsUpdateProcessorFactoryTest, TestOmitPositions, UUIDFieldTest, OpenExchangeRatesOrgProviderTest, StandardRequestHandlerTest, CollectionsAPIDistributedZkTest]
[junit4] Completed in 127.44s, 1 test, 1 error <<< FAILURES!
[...truncated 620 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:395: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:375: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:450: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1233: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:876: There were test failures: 325 suites, 1409 tests, 1 error, 40 ignored (5 assumptions)
Total time: 100 minutes 32 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure