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/06/18 17:10:15 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 557 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/557/
Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.lucene.index.TestFieldsReader.testExceptions
Error Message:
Java heap space
Stack Trace:
java.lang.OutOfMemoryError: Java heap space
at __randomizedtesting.SeedInfo.seed([3DDCA4155ACB41B0:4BDDF6BDF2B63F06]:0)
at org.apache.lucene.util.BytesRef.copyBytes(BytesRef.java:196)
at org.apache.lucene.util.BytesRef.deepCopyOf(BytesRef.java:343)
at org.apache.lucene.codecs.lucene3x.TermBuffer.toTerm(TermBuffer.java:113)
at org.apache.lucene.codecs.lucene3x.SegmentTermEnum.term(SegmentTermEnum.java:184)
at org.apache.lucene.codecs.lucene3x.Lucene3xFields$PreTermsEnum.next(Lucene3xFields.java:863)
at org.apache.lucene.index.MultiTermsEnum.pushTop(MultiTermsEnum.java:292)
at org.apache.lucene.index.MultiTermsEnum.next(MultiTermsEnum.java:318)
at org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:103)
at org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:365)
at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:98)
at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3767)
at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3371)
at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1887)
at org.apache.lucene.index.IndexWriter.forceMerge(IndexWriter.java:1697)
at org.apache.lucene.index.IndexWriter.forceMerge(IndexWriter.java:1650)
at org.apache.lucene.index.TestFieldsReader.testExceptions(TestFieldsReader.java:204)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
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 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)
Build Log:
[...truncated 1017 lines...]
[junit4:junit4] Suite: org.apache.lucene.index.TestFieldsReader
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestFieldsReader -Dtests.method=testExceptions -Dtests.seed=3DDCA4155ACB41B0 -Dtests.slow=true -Dtests.locale=sr_RS_#Latn -Dtests.timezone=Asia/Dhaka -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 8.16s | TestFieldsReader.testExceptions <<<
[junit4:junit4] > Throwable #1: java.lang.OutOfMemoryError: Java heap space
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([3DDCA4155ACB41B0:4BDDF6BDF2B63F06]:0)
[junit4:junit4] > at org.apache.lucene.util.BytesRef.copyBytes(BytesRef.java:196)
[junit4:junit4] > at org.apache.lucene.util.BytesRef.deepCopyOf(BytesRef.java:343)
[junit4:junit4] > at org.apache.lucene.codecs.lucene3x.TermBuffer.toTerm(TermBuffer.java:113)
[junit4:junit4] > at org.apache.lucene.codecs.lucene3x.SegmentTermEnum.term(SegmentTermEnum.java:184)
[junit4:junit4] > at org.apache.lucene.codecs.lucene3x.Lucene3xFields$PreTermsEnum.next(Lucene3xFields.java:863)
[junit4:junit4] > at org.apache.lucene.index.MultiTermsEnum.pushTop(MultiTermsEnum.java:292)
[junit4:junit4] > at org.apache.lucene.index.MultiTermsEnum.next(MultiTermsEnum.java:318)
[junit4:junit4] > at org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:103)
[junit4:junit4] > at org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
[junit4:junit4] > at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:365)
[junit4:junit4] > at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:98)
[junit4:junit4] > at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3767)
[junit4:junit4] > at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3371)
[junit4:junit4] > at org.apache.lucene.index.SerialMergeScheduler.merge(SerialMergeScheduler.java:40)
[junit4:junit4] > at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1887)
[junit4:junit4] > at org.apache.lucene.index.IndexWriter.forceMerge(IndexWriter.java:1697)
[junit4:junit4] > at org.apache.lucene.index.IndexWriter.forceMerge(IndexWriter.java:1650)
[junit4:junit4] > at org.apache.lucene.index.TestFieldsReader.testExceptions(TestFieldsReader.java:204)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=DefaultSimilarity, locale=sr_RS_#Latn, timezone=Asia/Dhaka
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=1,free=502829560,total=522190848
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDateFilter, TestLucene3xPostingsFormat, TestPayloads, TestLock, TestPriorityQueue, TestTermScorer, TestDocTermOrdsRangeFilter, TestBooleanOr, InBeforeClass, InAfterClass, InTestMethod, NonStringProperties, TestRollingUpdates, TestArrayUtil, TestDirectoryReader, Test2BPostingsBytes, TestNorms, TestBytesStore, TestLucene40PostingsReader, TestDirectory, TestMultiThreadTermVectors, TestFieldCacheRewriteMethod, TestRegexpRandom2, TestSubScorerFreqs, Nested1, Nested3, Nested2, TestStoredFieldsFormat, TestMultiValuedNumericRangeQuery, TestPayloadsOnVectors, TestWorstCaseTestBehavior, TestNRTThreads, TestNoMergePolicy, TestSortDocValues, TestTieredMergePolicy, TestCheckIndex, TestStressIndexing, TestDocTermOrds, TestCompoundFile, TestOmitNorms, TestTermRangeFilter, Nested1, TestCollectionUtil, TestInPlaceMergeSorter, TestFieldCacheTermsFilter, TestOpenBitSet, TestUniqueTermCount, TestNGramPhraseQuery, TestSpansAdvanced2, Test2BPositions, TestFuzzyQuery, TestLiveFieldValues, TestFastDecompressionMode, TestOmitPositions, Nested1, TestIntsRef, TestPayloadSpans, Nested1, TestSurrogates, TestSpans, TestMockCharFilter, TestIdentityHashSet, TestTerm, TestSmallFloat, Test2BDocs, TestDemo, TestFieldCacheSanityChecker, TestBoolean2, TestCloseableThreadLocal, TestIntBlockPool, TestSimilarityBase, TestCharsRef, TestBytesRefHash, TestLazyProxSkipping, TestSortRandom, TestMockDirectoryWrapper, TestLookaheadTokenFilter, TestIndexWriterNRTIsCurrent, TestLucene40StoredFieldsFormat, TestPrefixRandom, TestCodecHoldsOpenFiles, TestBitVector, TestAssertions, TestNumericRangeQuery64, TestSimilarityProvider, TestPayloadTermQuery, TestQueryWrapperFilter, TestSearchAfter, Nested, Nested, TestRamUsageEstimatorOnWildAnimals, TestFixedBitSet, TestPostingsOffsets, TestIndexWriterForceMerge, TestByteSlices, TestForceMergeForever, TestDeterminizeLexicon, TestFieldMaskingSpanQuery, TestPayloadExplanations, TestNewestSegment, TestCachingCollector, TestRecyclingIntBlockAllocator, TestIOUtils, TestIndexSearcher, TestIndexInput, TestScoreCachingWrappingScorer, TestDocumentWriter, TestTermVectorsWriter, TestMultiLevelSkipList, TestNumericUtils, TestIndexWriterMerging, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, Nested, TestMultiPhraseQuery, TestFileSwitchDirectory, TestRollback, TestIndexWriterWithThreads, TestAllFilesHaveCodecHeader, TestLucene40TermVectorsFormat, TestSort, TestSameTokenSamePosition, TestIndexCommit, TestMultiTermQueryRewrites, TestBlockPostingsFormat2, TestConjunctions, TestDoc, TestPositiveScoresOnlyCollector, TestFastCompressionMode, TestDocumentsWriterStallControl, TestDocIdSet, Nested, TestPrefixInBooleanQuery, TestNamedSPILoader, TestNRTCachingDirectory, TestMathUtil, TestSloppyPhraseQuery, TestAutomatonQueryUnicode, TestIndexWriterUnicode, TestFSTs, TestBytesRef, TestExternalCodecs, TestCompressingTermVectorsFormat, TestDeletionPolicy, TestLucene42DocValuesFormat, TestPackedInts, TestSloppyPhraseQuery2, TestTimeLimitingCollector, MultiCollectorTest, TestBagOfPositions, TestFieldCache, TestReaderClosed, TestCodecs, TestRegexpRandom, TestPhrasePrefixQuery, TestRateLimiter, TestBlockPostingsFormat3, TestIndexWriterExceptions, TestTransactions, TestField, TestSpanSearchEquivalence, TestNot, Test2BPostings, TestVersionComparator, TestUTF32ToUTF8, TestCachingWrapperFilter, TestBackwardsCompatibility3x, NestedSetupChain, NestedTeardownChain, TestBooleanScorer, TestConstantScoreQuery, TestPositionIncrement, ThrowInUncaught, TestVirtualMethod, TestCrashCausesCorruptIndex, TestTermdocPerf, TestWildcard, TestFilteredQuery, TestPrefixFilter, TestReuseDocsEnum, TestTermVectors, TestPrefixCodedTerms, TestPostingsFormat, Before3, Before3, TestFilterIterator, TestTwoPhaseCommitTool, TestLockFactory, TestBooleanQuery, TestDocValuesWithThreads, TestIndexWriter, TestPerFieldDocValuesFormat, TestDocValuesFormat, TestIndexWriterReader, TestTermVectorsFormat, TestNumericRangeQuery32, TestBackwardsCompatibility, TestGraphTokenizers, TestAddIndexes, TestShardSearching, TestMultiMMap, TestSearcherManager, TestBasics, TestFlushByRamOrCountsPolicy, TestIndexWriterDelete, TestLucene40DocValuesFormat, TestIndexWriterMergePolicy, TestDuelingCodecs, TestPersistentSnapshotDeletionPolicy, TestAtomicUpdate, TestStressAdvance, TestIndexWriterCommit, TestDirectoryReaderReopen, TestSearchWithThreads, TestConcurrentMergeScheduler, TestHighCompressionMode, TestNeverDelete, TestTopDocsMerge, TestLongPostings, TestMinimize, TestDocTermOrdsRewriteMethod, TestSnapshotDeletionPolicy, TestNRTReaderWithThreads, TestPerFieldPostingsFormat, TestLevenshteinAutomata, TestBufferedIndexInput, TestTermsEnum, TestConsistentFieldNumbers, TestWeakIdentityMap, TestSimpleExplanations, TestCompressingStoredFieldsFormat, TestSegmentMerger, TestPhraseQuery, TestDoubleBarrelLRUCache, TestComplexExplanations, TestMockAnalyzer, TestSegmentReader, TestParallelCompositeReader, TestPagedBytes, TestCrash, TestSegmentTermDocs, TestPerFieldPostingsFormat2, TestBlockPostingsFormat, TestMultiDocValues, TestToken, TestFieldsReader]
[junit4:junit4] Completed in 8.61s, 2 tests, 1 error <<< FAILURES!
[...truncated 405 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:392: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:372: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/build.xml:49: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1246: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:890: There were test failures: 364 suites, 2311 tests, 1 error, 64 ignored (51 assumptions)
Total time: 17 minutes 43 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 558 -
Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/558/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_0 expected:<73> but was:<72>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_0 expected:<73> but was:<72>
at __randomizedtesting.SeedInfo.seed([20845880F04DF68C:A162D698871296B0]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:209)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:162)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
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:722)
Build Log:
[...truncated 9380 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 918906 T1841 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 918912 T1841 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1371591122702
[junit4:junit4] 2> 918914 T1841 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 918915 T1842 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 919017 T1841 oasc.ZkTestServer.run start zk server on port:51893
[junit4:junit4] 2> 919019 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 919026 T1848 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11d08c31 name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 919027 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 919027 T1841 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 919040 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 919063 T1850 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d056abb name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 919064 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 919064 T1841 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 919077 T1841 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 919087 T1841 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 919095 T1841 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 919105 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 919107 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 919124 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 919125 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 919144 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 919147 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 919159 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 919160 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 919170 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 919172 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 919182 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/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:junit4] 2> 919184 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 919206 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/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:junit4] 2> 919212 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 919227 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/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:junit4] 2> 919228 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 919245 T1841 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 919247 T1841 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 919955 T1841 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 919972 T1841 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51896
[junit4:junit4] 2> 919973 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 919974 T1841 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 919974 T1841 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066
[junit4:junit4] 2> 919975 T1841 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/solr.xml
[junit4:junit4] 2> 919975 T1841 oasc.CoreContainer.<init> New CoreContainer 19625364
[junit4:junit4] 2> 919976 T1841 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/'
[junit4:junit4] 2> 919977 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/'
[junit4:junit4] 2> 920207 T1841 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 920208 T1841 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 920208 T1841 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 920209 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 920211 T1841 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 920214 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 920216 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 920218 T1841 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 920219 T1841 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 920221 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 920265 T1841 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 920266 T1841 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51893/solr
[junit4:junit4] 2> 920267 T1841 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 920271 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 920285 T1861 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f649d5 name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 920295 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 920310 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 920339 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 920347 T1863 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32b8dcd4 name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 920348 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 920355 T1841 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 920373 T1841 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 920391 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 920408 T1841 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51896_
[junit4:junit4] 2> 920414 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51896_
[junit4:junit4] 2> 920433 T1841 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 920453 T1841 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 920462 T1841 oasc.Overseer.start Overseer (id=89888595818119171-127.0.0.1:51896_-n_0000000000) starting
[junit4:junit4] 2> 920476 T1841 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 920493 T1865 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 920509 T1841 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 920521 T1841 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 920529 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 920552 T1866 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 920553 T1866 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 920557 T1864 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 920566 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 920568 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51896_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51896"}
[junit4:junit4] 2> 920569 T1864 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 920569 T1864 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 920583 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 921561 T1866 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/collection1
[junit4:junit4] 2> 921562 T1866 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 921565 T1866 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 921566 T1866 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 921572 T1866 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/collection1/'
[junit4:junit4] 2> 921574 T1866 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 921575 T1866 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/collection1/lib/README' to classloader
[junit4:junit4] 2> 921680 T1866 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 921841 T1866 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 921846 T1866 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 921859 T1866 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 923223 T1866 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 923233 T1866 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 923238 T1866 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 923252 T1866 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 923396 T1866 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 923397 T1866 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371591123066/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data/
[junit4:junit4] 2> 923397 T1866 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2adc675
[junit4:junit4] 2> 923398 T1866 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 923399 T1866 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data
[junit4:junit4] 2> 923400 T1866 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data/index/
[junit4:junit4] 2> 923400 T1866 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 923401 T1866 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data/index
[junit4:junit4] 2> 923409 T1866 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@3fe8abc1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ceb9cf2; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 923410 T1866 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 923415 T1866 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 923416 T1866 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 923418 T1866 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 923419 T1866 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 923421 T1866 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 923421 T1866 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 923422 T1866 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 923423 T1866 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 923426 T1866 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 923456 T1866 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 923481 T1866 oass.SolrIndexSearcher.<init> Opening Searcher@3d18e2c6 main
[junit4:junit4] 2> 923482 T1866 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/control/data/tlog
[junit4:junit4] 2> 923485 T1866 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 923486 T1866 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 923497 T1867 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d18e2c6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 923499 T1866 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 923499 T1866 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51896 collection:control_collection shard:shard1
[junit4:junit4] 2> 923502 T1866 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 923530 T1866 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 923540 T1866 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 923541 T1866 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 923541 T1866 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51896/collection1/
[junit4:junit4] 2> 923542 T1866 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 923542 T1866 oasc.SyncStrategy.syncToMe http://127.0.0.1:51896/collection1/ has no replicas
[junit4:junit4] 2> 923543 T1866 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51896/collection1/
[junit4:junit4] 2> 923543 T1866 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 923654 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 923702 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 923740 T1866 oasc.ZkController.register We are http://127.0.0.1:51896/collection1/ and leader is http://127.0.0.1:51896/collection1/
[junit4:junit4] 2> 923741 T1866 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51896
[junit4:junit4] 2> 923742 T1866 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 923742 T1866 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 923743 T1866 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 923751 T1866 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 923756 T1841 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 923757 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 923758 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 923806 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 923816 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 923824 T1870 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a40f903 name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 923828 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 923834 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 923845 T1841 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 924618 T1841 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 924631 T1841 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51900
[junit4:junit4] 2> 924633 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 924635 T1841 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 924647 T1841 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635
[junit4:junit4] 2> 924649 T1841 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/solr.xml
[junit4:junit4] 2> 924650 T1841 oasc.CoreContainer.<init> New CoreContainer 1194844075
[junit4:junit4] 2> 924651 T1841 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/'
[junit4:junit4] 2> 924652 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/'
[junit4:junit4] 2> 924925 T1841 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 924926 T1841 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 924927 T1841 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 924928 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 924928 T1841 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 924929 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 924930 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 924931 T1841 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 924931 T1841 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 924932 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 924978 T1841 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 924980 T1841 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51893/solr
[junit4:junit4] 2> 924981 T1841 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 924983 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 924993 T1881 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4aec7dff name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 924994 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 925009 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 925058 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 925101 T1883 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1abb7c4d name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 925102 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 925129 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 925226 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 925229 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51896_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51896"}
[junit4:junit4] 2> 925249 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 925265 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 925271 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 926144 T1841 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51900_
[junit4:junit4] 2> 926148 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51900_
[junit4:junit4] 2> 926155 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 926165 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 926169 T1883 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 926170 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 926169 T1863 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 926178 T1870 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 926194 T1884 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 926195 T1884 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 926772 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 926777 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51900_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51900"}
[junit4:junit4] 2> 926777 T1864 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 926777 T1864 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 926792 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 926793 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 926794 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 927200 T1884 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/collection1
[junit4:junit4] 2> 927201 T1884 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 927204 T1884 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 927204 T1884 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 927211 T1884 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/collection1/'
[junit4:junit4] 2> 927214 T1884 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 927215 T1884 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/collection1/lib/README' to classloader
[junit4:junit4] 2> 927350 T1884 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 927475 T1884 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 927479 T1884 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 927486 T1884 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 928442 T1884 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 928446 T1884 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 928450 T1884 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 928466 T1884 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 928554 T1884 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 928555 T1884 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371591127635/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1/
[junit4:junit4] 2> 928555 T1884 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2adc675
[junit4:junit4] 2> 928556 T1884 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 928557 T1884 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1
[junit4:junit4] 2> 928557 T1884 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1/index/
[junit4:junit4] 2> 928558 T1884 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 928559 T1884 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1/index
[junit4:junit4] 2> 928566 T1884 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 928566 T1884 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 928571 T1884 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 928572 T1884 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 928573 T1884 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 928575 T1884 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 928575 T1884 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 928576 T1884 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 928576 T1884 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 928577 T1884 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 928578 T1884 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 928603 T1884 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 928614 T1884 oass.SolrIndexSearcher.<init> Opening Searcher@7a9071db main
[junit4:junit4] 2> 928614 T1884 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty1/tlog
[junit4:junit4] 2> 928616 T1884 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 928616 T1884 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 928623 T1885 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a9071db main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 928627 T1884 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 928627 T1884 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51900 collection:collection1 shard:shard1
[junit4:junit4] 2> 928629 T1884 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 928671 T1884 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 928680 T1884 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 928680 T1884 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 928680 T1884 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51900/collection1/
[junit4:junit4] 2> 928681 T1884 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 928681 T1884 oasc.SyncStrategy.syncToMe http://127.0.0.1:51900/collection1/ has no replicas
[junit4:junit4] 2> 928681 T1884 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51900/collection1/
[junit4:junit4] 2> 928682 T1884 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 929856 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 929898 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 929911 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 929912 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 929945 T1884 oasc.ZkController.register We are http://127.0.0.1:51900/collection1/ and leader is http://127.0.0.1:51900/collection1/
[junit4:junit4] 2> 929945 T1884 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51900
[junit4:junit4] 2> 929946 T1884 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 929946 T1884 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 929947 T1884 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 929954 T1884 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 929967 T1841 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 929969 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 929970 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 930699 T1841 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 930713 T1841 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51903
[junit4:junit4] 2> 930715 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 930715 T1841 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 930716 T1841 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799
[junit4:junit4] 2> 930717 T1841 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/solr.xml
[junit4:junit4] 2> 930717 T1841 oasc.CoreContainer.<init> New CoreContainer 1177460404
[junit4:junit4] 2> 930718 T1841 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/'
[junit4:junit4] 2> 930719 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/'
[junit4:junit4] 2> 930986 T1841 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 930987 T1841 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 930988 T1841 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 930989 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 930989 T1841 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 930990 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 931000 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 931001 T1841 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 931001 T1841 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 931002 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 931026 T1841 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 931031 T1841 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51893/solr
[junit4:junit4] 2> 931034 T1841 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 931039 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 931043 T1897 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5ff47828 name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 931045 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 931050 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 931070 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 931075 T1899 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ccd8a2c name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 931076 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 931100 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 931438 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 931441 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51900_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51900"}
[junit4:junit4] 2> 931455 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 931456 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 931457 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 931458 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 932112 T1841 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51903_
[junit4:junit4] 2> 932115 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51903_
[junit4:junit4] 2> 932122 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 932128 T1863 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 932129 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 932136 T1870 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 932137 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 932152 T1883 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 932153 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 932154 T1899 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 932178 T1900 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 932179 T1900 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 932990 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 932992 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51903_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51903"}
[junit4:junit4] 2> 932993 T1864 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 932993 T1864 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 933007 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 933007 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 933013 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 933024 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 933189 T1900 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/collection1
[junit4:junit4] 2> 933189 T1900 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 933192 T1900 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 933192 T1900 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 933196 T1900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/collection1/'
[junit4:junit4] 2> 933198 T1900 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 933199 T1900 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/collection1/lib/README' to classloader
[junit4:junit4] 2> 933319 T1900 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 933489 T1900 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 933497 T1900 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 933508 T1900 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 934574 T1900 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 934578 T1900 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 934581 T1900 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 934595 T1900 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 934707 T1900 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 934707 T1900 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371591133799/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2/
[junit4:junit4] 2> 934708 T1900 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2adc675
[junit4:junit4] 2> 934708 T1900 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 934710 T1900 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2
[junit4:junit4] 2> 934710 T1900 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2/index/
[junit4:junit4] 2> 934710 T1900 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 934712 T1900 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2/index
[junit4:junit4] 2> 934718 T1900 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 934718 T1900 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 934723 T1900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 934724 T1900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 934725 T1900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 934726 T1900 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 934727 T1900 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 934728 T1900 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 934729 T1900 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 934729 T1900 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 934730 T1900 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 934762 T1900 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 934777 T1900 oass.SolrIndexSearcher.<init> Opening Searcher@4f332d80 main
[junit4:junit4] 2> 934778 T1900 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty2/tlog
[junit4:junit4] 2> 934781 T1900 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 934785 T1900 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 934795 T1901 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4f332d80 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 934799 T1900 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 934799 T1900 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51903 collection:collection1 shard:shard2
[junit4:junit4] 2> 934801 T1900 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 934823 T1900 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 934837 T1900 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 934838 T1900 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 934838 T1900 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51903/collection1/
[junit4:junit4] 2> 934838 T1900 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 934839 T1900 oasc.SyncStrategy.syncToMe http://127.0.0.1:51903/collection1/ has no replicas
[junit4:junit4] 2> 934839 T1900 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51903/collection1/
[junit4:junit4] 2> 934839 T1900 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 936082 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 936114 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 936115 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 936115 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 936120 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 936156 T1900 oasc.ZkController.register We are http://127.0.0.1:51903/collection1/ and leader is http://127.0.0.1:51903/collection1/
[junit4:junit4] 2> 936156 T1900 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51903
[junit4:junit4] 2> 936157 T1900 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 936157 T1900 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 936157 T1900 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 936162 T1900 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 936170 T1841 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 936171 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 936172 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 936822 T1841 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 936833 T1841 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51906
[junit4:junit4] 2> 936838 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 936839 T1841 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 936842 T1841 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988
[junit4:junit4] 2> 936843 T1841 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/solr.xml
[junit4:junit4] 2> 936843 T1841 oasc.CoreContainer.<init> New CoreContainer 483860122
[junit4:junit4] 2> 936844 T1841 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/'
[junit4:junit4] 2> 936845 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/'
[junit4:junit4] 2> 937067 T1841 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 937072 T1841 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 937072 T1841 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 937073 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 937073 T1841 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 937074 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 937074 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 937074 T1841 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 937075 T1841 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 937075 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 937113 T1841 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 937114 T1841 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51893/solr
[junit4:junit4] 2> 937115 T1841 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 937117 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 937125 T1913 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6fd9f2de name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 937126 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 937134 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 937158 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 937171 T1915 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22b2419c name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 937172 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 937187 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 937648 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 937650 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51903_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51903"}
[junit4:junit4] 2> 937669 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 937669 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 937669 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 937669 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 937669 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 938201 T1841 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51906_
[junit4:junit4] 2> 938205 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51906_
[junit4:junit4] 2> 938211 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 938212 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 938213 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 938218 T1915 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 938218 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 938219 T1883 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 938219 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 938226 T1863 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 938226 T1870 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 938229 T1899 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 938244 T1916 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 938245 T1916 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 939205 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 939207 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51906_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51906"}
[junit4:junit4] 2> 939208 T1864 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 939208 T1864 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 939223 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 939224 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 939224 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 939223 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 939223 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 939248 T1916 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/collection1
[junit4:junit4] 2> 939249 T1916 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 939250 T1916 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 939250 T1916 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 939254 T1916 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/collection1/'
[junit4:junit4] 2> 939255 T1916 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 939256 T1916 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/collection1/lib/README' to classloader
[junit4:junit4] 2> 939330 T1916 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 939456 T1916 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 939460 T1916 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 939474 T1916 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 940421 T1916 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 940425 T1916 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 940430 T1916 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 940440 T1916 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 940540 T1916 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 940541 T1916 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371591139988/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/
[junit4:junit4] 2> 940541 T1916 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2adc675
[junit4:junit4] 2> 940542 T1916 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 940543 T1916 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3
[junit4:junit4] 2> 940543 T1916 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index/
[junit4:junit4] 2> 940544 T1916 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 940546 T1916 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index
[junit4:junit4] 2> 940558 T1916 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@143fee62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f6aefe9; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 940558 T1916 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 940563 T1916 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 940564 T1916 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 940565 T1916 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 940566 T1916 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 940567 T1916 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 940567 T1916 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 940568 T1916 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 940569 T1916 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 940569 T1916 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 940590 T1916 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 940602 T1916 oass.SolrIndexSearcher.<init> Opening Searcher@7a017938 main
[junit4:junit4] 2> 940602 T1916 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/tlog
[junit4:junit4] 2> 940608 T1916 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 940610 T1916 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 940617 T1917 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a017938 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 940624 T1916 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 940624 T1916 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51906 collection:collection1 shard:shard1
[junit4:junit4] 2> 940635 T1916 oasc.ZkController.register We are http://127.0.0.1:51906/collection1/ and leader is http://127.0.0.1:51900/collection1/
[junit4:junit4] 2> 940635 T1916 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51906
[junit4:junit4] 2> 940636 T1916 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 940636 T1916 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C920 name=collection1 org.apache.solr.core.SolrCore@8bcc6da url=http://127.0.0.1:51906/collection1 node=127.0.0.1:51906_ C920_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51906_, base_url=http://127.0.0.1:51906}
[junit4:junit4] 2> 940637 T1918 C920 P51906 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 940639 T1918 C920 P51906 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 940639 T1918 C920 P51906 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 940639 T1918 C920 P51906 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 940642 T1916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 940644 T1918 C920 P51906 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 940648 T1841 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 940648 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 940649 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 940700 T1875 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 940772 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 940779 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51906_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51906"}
[junit4:junit4] 2> 940813 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 940814 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 940816 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 940819 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 940819 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 941346 T1841 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 941356 T1841 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51910
[junit4:junit4] 2> 941357 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 941358 T1841 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 941359 T1841 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485
[junit4:junit4] 2> 941360 T1841 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/solr.xml
[junit4:junit4] 2> 941360 T1841 oasc.CoreContainer.<init> New CoreContainer 935965009
[junit4:junit4] 2> 941361 T1841 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/'
[junit4:junit4] 2> 941361 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/'
[junit4:junit4] 2> 941559 T1841 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 941560 T1841 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 941560 T1841 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 941561 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 941562 T1841 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 941565 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 941569 T1841 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 941570 T1841 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 941571 T1841 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 941572 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 941602 T1841 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 941604 T1841 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51893/solr
[junit4:junit4] 2> 941604 T1841 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 941607 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 941614 T1930 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@252a77e1 name:ZooKeeperConnection Watcher:127.0.0.1:51893 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 941615 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 941623 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 941623 T1843 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f59339f19000b, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 941653 T1841 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 941658 T1932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64656737 name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 941658 T1841 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 941676 T1841 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 941702 T1875 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 941703 T1875 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:51906_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 942691 T1841 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51910_
[junit4:junit4] 2> 942698 T1841 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51910_
[junit4:junit4] 2> 942718 T1915 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942718 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 942719 T1883 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942719 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 942735 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 942741 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 942742 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 942760 T1932 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942765 T1863 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942767 T1870 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942769 T1899 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 942777 T1933 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 942778 T1933 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C921 name=collection1 org.apache.solr.core.SolrCore@8bcc6da url=http://127.0.0.1:51906/collection1 node=127.0.0.1:51906_ C921_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51906_, base_url=http://127.0.0.1:51906}
[junit4:junit4] 2> 943711 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51900/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 943711 T1918 C921 P51906 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51906 START replicas=[http://127.0.0.1:51900/collection1/] nUpdates=100
[junit4:junit4] 2> 943712 T1918 C921 P51906 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 943713 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 943713 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 943714 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 943777 T1918 C921 P51906 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 943778 T1918 C921 P51906 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51900/collection1/. core=collection1
[junit4:junit4] 2> ASYNC NEW_CORE C922 name=collection1 org.apache.solr.core.SolrCore@7670932d url=http://127.0.0.1:51900/collection1 node=127.0.0.1:51900_ C922_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51900_, base_url=http://127.0.0.1:51900, leader=true}
[junit4:junit4] 2> 943777 T1878 C922 P51900 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=36
[junit4:junit4] 2> 943778 T1918 C921 P51906 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 943806 T1879 C922 P51900 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 943811 T1879 C922 P51900 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 943812 T1879 C922 P51900 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 943813 T1879 C922 P51900 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 943814 T1879 C922 P51900 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 943815 T1879 C922 P51900 oass.SolrIndexSearcher.<init> Opening Searcher@33277906 realtime
[junit4:junit4] 2> 943815 T1879 C922 P51900 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 943816 T1879 C922 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 943818 T1918 C921 P51906 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 943818 T1918 C921 P51906 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 943825 T1876 C922 P51900 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 943825 T1876 C922 P51900 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 943826 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 943826 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 943827 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 943830 T1877 C922 P51900 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 943837 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 943840 T1918 C921 P51906 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index.20130618123227627
[junit4:junit4] 2> 943841 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@26bbd9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@5dc87d98) fullCopy=false
[junit4:junit4] 2> 943849 T1875 C922 P51900 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 943851 T1918 C921 P51906 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 943853 T1918 C921 P51906 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 943853 T1918 C921 P51906 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 943857 T1918 C921 P51906 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@143fee62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f6aefe9; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@143fee62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f6aefe9; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 943858 T1918 C921 P51906 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 943859 T1918 C921 P51906 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 943860 T1918 C921 P51906 oass.SolrIndexSearcher.<init> Opening Searcher@21fbca7f main
[junit4:junit4] 2> 943862 T1917 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21fbca7f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 943863 T1918 C921 P51906 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index.20130618123227627 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index.20130618123227627;done=true>>]
[junit4:junit4] 2> 943864 T1918 C921 P51906 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index.20130618123227627
[junit4:junit4] 2> 943864 T1918 C921 P51906 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty3/index.20130618123227627
[junit4:junit4] 2> 943865 T1918 C921 P51906 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 943865 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 943866 T1918 C921 P51906 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 943867 T1918 C921 P51906 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 943871 T1918 C921 P51906 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 943892 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 943894 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51910_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51910"}
[junit4:junit4] 2> 943895 T1864 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 943895 T1864 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 943909 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51906_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51906"}
[junit4:junit4] 2> 943925 T1932 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 943925 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 943926 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 943936 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 943936 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 943937 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 944783 T1933 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/collection1
[junit4:junit4] 2> 944784 T1933 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 944786 T1933 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 944786 T1933 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 944790 T1933 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/collection1/'
[junit4:junit4] 2> 944792 T1933 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 944792 T1933 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/collection1/lib/README' to classloader
[junit4:junit4] 2> 944901 T1933 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 945025 T1933 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 945030 T1933 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 945037 T1933 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 945958 T1933 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 945964 T1933 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 945967 T1933 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 945976 T1933 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 946081 T1933 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 946082 T1933 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371591144485/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/
[junit4:junit4] 2> 946082 T1933 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2adc675
[junit4:junit4] 2> 946083 T1933 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 946084 T1933 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4
[junit4:junit4] 2> 946084 T1933 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index/
[junit4:junit4] 2> 946084 T1933 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 946085 T1933 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index
[junit4:junit4] 2> 946090 T1933 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@688830cd lockFactory=org.apache.lucene.store.NativeFSLockFactory@72f94706; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 946091 T1933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 946095 T1933 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 946096 T1933 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 946096 T1933 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 946098 T1933 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 946099 T1933 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 946099 T1933 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 946152 T1933 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 946153 T1933 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 946154 T1933 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 946175 T1933 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 946184 T1933 oass.SolrIndexSearcher.<init> Opening Searcher@3ca2eb71 main
[junit4:junit4] 2> 946185 T1933 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/tlog
[junit4:junit4] 2> 946186 T1933 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 946187 T1933 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 946196 T1933 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 946196 T1933 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51910 collection:collection1 shard:shard2
[junit4:junit4] 2> 946198 T1936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ca2eb71 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 946206 T1933 oasc.ZkController.register We are http://127.0.0.1:51910/collection1/ and leader is http://127.0.0.1:51903/collection1/
[junit4:junit4] 2> 946207 T1933 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51910
[junit4:junit4] 2> 946208 T1933 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 946210 T1933 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C923 name=collection1 org.apache.solr.core.SolrCore@7301adfb url=http://127.0.0.1:51910/collection1 node=127.0.0.1:51910_ C923_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51910_, base_url=http://127.0.0.1:51910}
[junit4:junit4] 2> 946214 T1937 C923 P51910 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 946215 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 946216 T1937 C923 P51910 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 946216 T1937 C923 P51910 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 946216 T1933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 946219 T1937 C923 P51910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 946223 T1841 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 946223 T1841 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 946224 T1841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 946269 T1891 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 946270 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 946273 T1841 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 946274 T1841 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 946276 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 946969 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 946971 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51910_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51910"}
[junit4:junit4] 2> 946989 T1932 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 946990 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 946989 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 946991 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 946999 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 947004 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 947271 T1891 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 947272 T1891 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:51910_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 947281 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 948286 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C923_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51910_, base_url=http://127.0.0.1:51910}
[junit4:junit4] 2> 949277 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51903/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 949278 T1937 C923 P51910 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51910 START replicas=[http://127.0.0.1:51903/collection1/] nUpdates=100
[junit4:junit4] 2> 949279 T1937 C923 P51910 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 949279 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 949279 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 949280 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 949280 T1937 C923 P51910 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 949281 T1937 C923 P51910 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51903/collection1/. core=collection1
[junit4:junit4] 2> 949281 T1937 C923 P51910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C924 name=collection1 org.apache.solr.core.SolrCore@60d3fbf0 url=http://127.0.0.1:51903/collection1 node=127.0.0.1:51903_ C924_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51903_, base_url=http://127.0.0.1:51903, leader=true}
[junit4:junit4] 2> 949341 T1894 C924 P51903 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=47
[junit4:junit4] 2> 949343 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 949363 T1890 C924 P51903 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 949369 T1890 C924 P51903 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 949370 T1890 C924 P51903 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 949371 T1890 C924 P51903 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 949372 T1890 C924 P51903 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 949373 T1890 C924 P51903 oass.SolrIndexSearcher.<init> Opening Searcher@3a51ce81 realtime
[junit4:junit4] 2> 949374 T1890 C924 P51903 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 949374 T1890 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 949376 T1937 C923 P51910 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 949376 T1937 C923 P51910 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 949383 T1892 C924 P51903 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 949384 T1892 C924 P51903 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 949385 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 949385 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 949386 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 949389 T1891 C924 P51903 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 949390 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 949392 T1937 C923 P51910 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index.20130618123233179
[junit4:junit4] 2> 949392 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7469bea5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39a2d13b) fullCopy=false
[junit4:junit4] 2> 949396 T1894 C924 P51903 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 949398 T1937 C923 P51910 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 949401 T1937 C923 P51910 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 949401 T1937 C923 P51910 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 949408 T1937 C923 P51910 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@688830cd lockFactory=org.apache.lucene.store.NativeFSLockFactory@72f94706; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@688830cd lockFactory=org.apache.lucene.store.NativeFSLockFactory@72f94706; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 949413 T1937 C923 P51910 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 949414 T1937 C923 P51910 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 949415 T1937 C923 P51910 oass.SolrIndexSearcher.<init> Opening Searcher@12e25589 main
[junit4:junit4] 2> 949417 T1936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12e25589 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 949417 T1937 C923 P51910 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index.20130618123233179 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index.20130618123233179;done=true>>]
[junit4:junit4] 2> 949418 T1937 C923 P51910 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index.20130618123233179
[junit4:junit4] 2> 949418 T1937 C923 P51910 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index.20130618123233179
[junit4:junit4] 2> 949418 T1937 C923 P51910 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 949419 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 949419 T1937 C923 P51910 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 949419 T1937 C923 P51910 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 949423 T1937 C923 P51910 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 950031 T1864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 950034 T1864 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51910_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51910"}
[junit4:junit4] 2> 950047 T1870 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950047 T1899 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950048 T1863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950048 T1883 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950050 T1932 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950051 T1915 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 950352 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 950354 T1841 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C925 name=collection1 org.apache.solr.core.SolrCore@37dcced9 url=http://127.0.0.1:51896/collection1 node=127.0.0.1:51896_ C925_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51896_, base_url=http://127.0.0.1:51896, leader=true}
[junit4:junit4] 2> 950374 T1856 C925 P51896 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 950379 T1856 C925 P51896 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@3fe8abc1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ceb9cf2; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 950381 T1856 C925 P51896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 950383 T1856 C925 P51896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@3fe8abc1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ceb9cf2; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@3fe8abc1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ceb9cf2; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 950383 T1856 C925 P51896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 950384 T1856 C925 P51896 oass.SolrIndexSearcher.<init> Opening Searcher@40dbe769 main
[junit4:junit4] 2> 950385 T1856 C925 P51896 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 950386 T1867 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40dbe769 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 950387 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> ASYNC NEW_CORE C926 name=collection1 org.apache.solr.core.SolrCore@8bcc6da url=http://127.0.0.1:51906/collection1 node=127.0.0.1:51906_ C926_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51906_, base_url=http://127.0.0.1:51906}
[junit4:junit4] 2> 950417 T1909 C926 P51906 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51900/collection1/, StdNode: http://127.0.0.1:51906/collection1/, StdNode: http://127.0.0.1:51903/collection1/, StdNode: http://127.0.0.1:51910/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C923_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51910_, base_url=http://127.0.0.1:51910}
[junit4:junit4] 2> 950484 T1926 C923 P51910 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C927 name=collection1 org.apache.solr.core.SolrCore@7670932d url=http://127.0.0.1:51900/collection1 node=127.0.0.1:51900_ C927_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51900_, base_url=http://127.0.0.1:51900, leader=true}
[junit4:junit4] 2> 950485 T1876 C927 P51900 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 950502 T1893 C924 P51903 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 950502 T1926 C923 P51910 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@688830cd lockFactory=org.apache.lucene.store.NativeFSLockFactory@72f94706; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@688830cd lockFactory=org.apache.lucene.store.NativeFSLockFactory@72f94706; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 950504 T1926 C923 P51910 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 950502 T1876 C927 P51900 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@54128f70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@57306ab6; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 950509 T1876 C927 P51900 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 950511 T1876 C927 P51900 oass.SolrIndexSearcher.<init> Opening Searcher@47a2da98 main
[junit4:junit4] 2> 950511 T1910 C926 P51906 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 950512 T1876 C927 P51900 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 950516 T1893 C924 P51903 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@459b1835 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124a9bf0; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 950517 T1926 C923 P51910 oass.SolrIndexSearcher.<init> Opening Searcher@bbb5202 main
[junit4:junit4] 2> 950517 T1893 C924 P51903 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 950518 T1893 C924 P51903 oass.SolrIndexSearcher.<init> Opening Searcher@352d2eda main
[junit4:junit4] 2> 950519 T1893 C924 P51903 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 950520 T1901 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@352d2eda main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 950516 T1885 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@47a2da98 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 950521 T1910 C926 P51906 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@143fee62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f6aefe9; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@143fee62 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f6aefe9; maxCacheMB=0.263671875 maxMergeSizeMB=0.7001953125)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 950522 T1910 C926 P51906 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 950521 T1893 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 950519 T1936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bbb5202 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 950518 T1926 C923 P51910 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 950528 T1926 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 46
[junit4:junit4] 2> 950526 T1910 C926 P51906 oass.SolrIndexSearcher.<init> Opening Searcher@54cb6055 main
[junit4:junit4] 2> 950530 T1910 C926 P51906 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 950521 T1876 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 36
[junit4:junit4] 2> 950533 T1917 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54cb6055 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 950534 T1910 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 950536 T1909 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 119
[junit4:junit4] 2> 950540 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 950546 T1877 C927 P51900 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 950552 T1905 C926 P51906 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 950557 T1892 C924 P51903 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 950563 T1927 C923 P51910 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 952571 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438217568370294784)} 0 2
[junit4:junit4] 2> 952623 T1907 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438217568386023424&update.from=http://127.0.0.1:51900/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438217568386023424)} 0 2
[junit4:junit4] 2> 952625 T1877 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438217568386023424)} 0 41
[junit4:junit4] 2> 952633 T1926 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438217568386023424&update.from=http://127.0.0.1:51903/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438217568386023424)} 0 2
[junit4:junit4] 2> 952635 T1892 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438217568386023424)} 0 51
[junit4:junit4] 2> 952637 T1905 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 62
[junit4:junit4] 2> 952644 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1438217568445792256)]} 0 2
[junit4:junit4] 2> 952662 T1927 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438217568458375168)]} 0 4
[junit4:junit4] 2> 952668 T1891 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438217568458375168)]} 0 15
[junit4:junit4] 2> 952669 T1908 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 20
[junit4:junit4] 2> 952676 T1858 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1438217568480395264)]} 0 2
[junit4:junit4] 2> 952700 T1910 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438217568496123904)]} 0 2
[junit4:junit4] 2> 952703 T1875 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1438217568496123904)]} 0 13
[junit4:junit4] 2> 952705 T1928 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 22
[junit4:junit4] 2> 952712 T1859 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1438217568518144000)]} 0 1
[junit4:junit4] 2> 952728 T1909 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438217568528629760)]} 0 2
[junit4:junit4] 2> 952729 T1878 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438217568528629760)]} 0 8
[junit4:junit4] 2> 952730 T1923 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 13
[junit4:junit4] 2> 952735 T1854 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438217568543309824)]} 0 1
[junit4:junit4] 2> 952752 T1924 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438217568552747008)]} 0 1
[junit4:junit4] 2> 952754 T1894 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1438217568552747008)]} 0 10
[junit4:junit4] 2> 952755 T1879 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 15
[junit4:junit4] 2> 952760 T1855 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1438217568569524224)]} 0 1
[junit4:junit4] 2> 952778 T1926 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438217568577912832)]} 0 4
[junit4:junit4] 2> 952779 T1895 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1438217568577912832)]} 0 11
[junit4:junit4] 2> 952780 T1925 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4]} 0 16
[junit4:junit4] 2> 952786 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1438217568595738624)]} 0 1
[junit4:junit4] 2> 952800 T1928 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438217568605175808)]} 0 2
[junit4:junit4] 2> 952802 T1890 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438217568605175808)]} 0 8
[junit4:junit4] 2> 952804 T1927 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 13
[junit4:junit4] 2> 952811 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438217568621953024)]} 0 2
[junit4:junit4] 2> 952825 T1906 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438217568632438784)]} 0 1
[junit4:junit4] 2> 952827 T1874 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438217568632438784)]} 0 7
[junit4:junit4] 2> 952829 T1923 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 13
[junit4:junit4] 2> 952836 T1859 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1438217568648167424)]} 0 1
[junit4:junit4] 2> 952855 T1907 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438217568658653184)]} 0 4
[junit4:junit4] 2> 952857 T1876 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1438217568658653184)]} 0 13
[junit4:junit4] 2> 952859 T1924 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 18
[junit4:junit4] 2> 952864 T1854 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438217568677527552)]} 0 1
[junit4:junit4] 2> 952877 T1905 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438217568686964736)]} 0 1
[junit4:junit4] 2> 952879 T1877 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1438217568686964736)]} 0 7
[junit4:junit4] 2> 952881 T1926 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 11
[junit4:junit4] 2> 952885 T1855 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1438217568700596224)]} 0 1
[junit4:junit4] 2> 952897 T1908 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438217568707936256)]} 0 1
[junit4:junit4] 2> 952899 T1875 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438217568707936256)]} 0 7
[junit4:junit4] 2> 952900 T1925 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9]} 0 11
[junit4:junit4] 2> 952911 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1438217568726810624)]} 0 2
[junit4:junit4] 2> 952922 T1910 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438217568735199232)]} 0 0
[junit4:junit4] 2> 952924 T1878 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1438217568735199232)]} 0 6
[junit4:junit4] 2> 952925 T1928 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 10
[junit4:junit4] 2> 952932 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438217568748830720)]} 0 2
[junit4:junit4] 2> 952942 T1927 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438217568755122176)]} 0 1
[junit4:junit4] 2> 952944 T1893 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438217568755122176)]} 0 7
[junit4:junit4] 2> 952949 T1858 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1438217568766656512)]} 0 1
[junit4:junit4] 2> 952964 T1923 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438217568778190848)]} 0 1
[junit4:junit4] 2> 952966 T1892 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1438217568778190848)]} 0 8
[junit4:junit4] 2> 952969 T1909 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 16
[junit4:junit4] 2> 952980 T1859 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438217568799162368)]} 0 1
[junit4:junit4] 2> 952990 T1907 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438217568805453824)]} 0 1
[junit4:junit4] 2> 952994 T1879 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438217568805453824)]} 0 10
[junit4:junit4] 2> 953001 T1854 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438217568821182464)]} 0 1
[junit4:junit4] 2> 953021 T1924 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438217568835862528)]} 0 1
[junit4:junit4] 2> 953023 T1894 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438217568835862528)]} 0 9
[junit4:junit4] 2> 953028 T1855 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1438217568850542592)]} 0 1
[junit4:junit4] 2> 953045 T1905 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438217568865222656)]} 0 0
[junit4:junit4] 2> 953047 T1876 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1438217568865222656)]} 0 6
[junit4:junit4] 2> 953048 T1925 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 13
[junit4:junit4] 2> 953053 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1438217568875708416)]} 0 1
[junit4:junit4] 2> 953070 T1908 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438217568888291328)]} 0 1
[junit4:junit4] 2> 953073 T1877 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438217568888291328)]} 0 9
[junit4:junit4] 2> 953075 T1895 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 17
[junit4:junit4] 2> 953081 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438217568905068544)]} 0 1
[junit4:junit4] 2> 953095 T1927 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438217568915554304)]} 0 1
[junit4:junit4] 2> 953097 T1890 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1438217568915554304)]} 0 7
[junit4:junit4] 2> 953099 T1928 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 13
[junit4:junit4] 2> 953102 T1858 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1438217568928137216)]} 0 0
[junit4:junit4] 2> 953117 T1910 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438217568938622976)]} 0 0
[junit4:junit4] 2> 953119 T1875 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1438217568938622976)]} 0 10
[junit4:junit4] 2> 953125 T1859 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1438217568952254464)]} 0 1
[junit4:junit4] 2> 953136 T1906 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438217568960643072)]} 0 0
[junit4:junit4] 2> 953138 T1878 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1438217568960643072)]} 0 5
[junit4:junit4] 2> 953139 T1909 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 9
[junit4:junit4] 2> 953144 T1854 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1438217568971128832)]} 0 1
[junit4:junit4] 2> 953156 T1923 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438217568979517440)]} 0 1
[junit4:junit4] 2> 953158 T1893 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1438217568979517440)]} 0 7
[junit4:junit4] 2> 953159 T1874 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 11
[junit4:junit4] 2> 953164 T1855 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438217568992100352)]} 0 1
[junit4:junit4] 2> 953182 T1907 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438217569006780416)]} 0 1
[junit4:junit4] 2> 953184 T1879 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1438217569006780416)]} 0 9
[junit4:junit4] 2> 953186 T1892 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21]} 0 18
[junit4:junit4] 2> 953194 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438217569023557632)]} 0 1
[junit4:junit4] 2> 953207 T1905 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438217569032994816)]} 0 1
[junit4:junit4] 2> 953213 T1876 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438217569032994816)]} 0 12
[junit4:junit4] 2> 953221 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438217569051869184)]} 0 2
[junit4:junit4] 2> 953237 T1924 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438217569064452096)]} 0 1
[junit4:junit4] 2> 953239 T1891 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1438217569064452096)]} 0 7
[junit4:junit4] 2> 953241 T1908 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 14
[junit4:junit4] 2> 953248 T1859 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1438217569080180736)]} 0 2
[junit4:junit4] 2> 953269 T1926 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438217569089617920)]} 0 5
[junit4:junit4] 2> 953271 T1894 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1438217569089617920)]} 0 15
[junit4:junit4] 2> 953273 T1877 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 21
[junit4:junit4] 2> 953279 T1854 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438217569112686592)]} 0 2
[junit4:junit4] 2> 953303 T1906 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438217569134706688)]} 0 1
[junit4:junit4] 2> 953304 T1875 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1438217569134706688)]} 0 6
[junit4:junit4] 2> 953306 T1910 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 18
[junit4:junit4] 2> 953310 T1855 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1438217569146241024)]} 0 1
[junit4:junit4] 2> 953321 T1925 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438217569153581056)]} 0 1
[junit4:junit4] 2> 953323 T1895 C924 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438217569153581056)]} 0 6
[junit4:junit4] 2> 953324 T1878 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 10
[junit4:junit4] 2> 953329 T1856 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1438217569165115392)]} 0 1
[junit4:junit4] 2> 953340 T1909 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438217569173504000)]} 0 1
[junit4:junit4] 2> 953341 T1874 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438217569173504000)]} 0 5
[junit4:junit4] 2> 953343 T1927 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 10
[junit4:junit4] 2> 953349 T1858 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1438217569186086912)]} 0 1
[junit4:junit4] 2> 953366 T1907 C926 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438217569196572672)]} 0 1
[junit4:junit4] 2> 953368 T1879 C927 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1438217569196572672)]} 0 11
[junit4:junit4] 2> 953369 T1928 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 16
[junit4:junit4] 2> 953374 T1857 C925 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1438217569213349888)]} 0 1
[junit4:junit4] 2> 953386 T1923 C923 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438217569220689920)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C928 name=collection1 org.apache.solr.core.SolrCore@60d3fbf0 url=http://127.0.0.1:51903/collection1 node=127.0.0.1:51903_ C928_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51903_, base_url=http://127.0.0.1:51903, leader=true}
[junit4:junit4] 2> 953409 T1890 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1438217569220689920)]} 0 28
[junit4:junit4] 2> ASYNC NEW_CORE C929 name=collection1 org.apache.solr.core.SolrCore@37dcced9 url=http://127.0.0.1:51896/collection1 node=127.0.0.1:51896_ C929_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51896_, base_url=http://127.0.0.1:51896, leader=true}
[junit4:junit4] 2> 953415 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1438217569255292928)]} 0 2
[junit4:junit4] 2> ASYNC NEW_CORE C930 name=collection1 org.apache.solr.core.SolrCore@7301adfb url=http://127.0.0.1:51910/collection1 node=127.0.0.1:51910_ C930_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51910_, base_url=http://127.0.0.1:51910}
[junit4:junit4] 2> 953428 T1926 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438217569264730112)]} 0 1
[junit4:junit4] 2> 953430 T1892 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438217569264730112)]} 0 7
[junit4:junit4] 2> 953431 T1924 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 11
[junit4:junit4] 2> 953436 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1438217569277313024)]} 0 1
[junit4:junit4] 2> 953453 T1928 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438217569288847360)]} 0 0
[junit4:junit4] 2> 953455 T1891 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438217569288847360)]} 0 11
[junit4:junit4] 2> 953456 T1927 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 16
[junit4:junit4] 2> 953460 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438217569303527424)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C931 name=collection1 org.apache.solr.core.SolrCore@8bcc6da url=http://127.0.0.1:51906/collection1 node=127.0.0.1:51906_ C931_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51906_, base_url=http://127.0.0.1:51906}
[junit4:junit4] 2> 953474 T1905 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438217569314013184)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C932 name=collection1 org.apache.solr.core.SolrCore@7670932d url=http://127.0.0.1:51900/collection1 node=127.0.0.1:51900_ C932_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51900_, base_url=http://127.0.0.1:51900, leader=true}
[junit4:junit4] 2> 953476 T1876 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1438217569314013184)]} 0 5
[junit4:junit4] 2> 953477 T1923 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 10
[junit4:junit4] 2> 953481 T1856 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438217569325547520)]} 0 0
[junit4:junit4] 2> 953489 T1906 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438217569329741824)]} 0 1
[junit4:junit4] 2> 953491 T1875 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438217569329741824)]} 0 6
[junit4:junit4] 2> 953496 T1858 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1438217569341276160)]} 0 1
[junit4:junit4] 2> 953514 T1910 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438217569348616192)]} 0 3
[junit4:junit4] 2> 953516 T1878 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438217569348616192)]} 0 14
[junit4:junit4] 2> 953517 T1894 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 17
[junit4:junit4] 2> 953523 T1857 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438217569368539136)]} 0 1
[junit4:junit4] 2> 953543 T1909 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438217569386364928)]} 0 1
[junit4:junit4] 2> 953545 T1874 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438217569386364928)]} 0 7
[junit4:junit4] 2> 953551 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438217569397899264)]} 0 2
[junit4:junit4] 2> 953565 T1907 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438217569409433600)]} 0 1
[junit4:junit4] 2> 953568 T1879 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1438217569409433600)]} 0 8
[junit4:junit4] 2> 953570 T1926 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36]} 0 14
[junit4:junit4] 2> 953576 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1438217569424113664)]} 0 1
[junit4:junit4] 2> 953598 T1925 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438217569438793728)]} 0 2
[junit4:junit4] 2> 953601 T1895 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438217569438793728)]} 0 12
[junit4:junit4] 2> 953603 T1908 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 22
[junit4:junit4] 2> 953609 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438217569459765248)]} 0 1
[junit4:junit4] 2> 953625 T1928 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438217569470251008)]} 0 1
[junit4:junit4] 2> 953627 T1893 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1438217569470251008)]} 0 8
[junit4:junit4] 2> 953630 T1924 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 15
[junit4:junit4] 2> 953639 T1856 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438217569489125376)]} 0 4
[junit4:junit4] 2> 953664 T1905 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438217569511145472)]} 0 2
[junit4:junit4] 2> 953666 T1877 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438217569511145472)]} 0 8
[junit4:junit4] 2> 953673 T1857 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1438217569525825536)]} 0 1
[junit4:junit4] 2> 953685 T1923 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438217569535262720)]} 0 1
[junit4:junit4] 2> 953687 T1890 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438217569535262720)]} 0 6
[junit4:junit4] 2> 953688 T1927 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 10
[junit4:junit4] 2> 953694 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1438217569547845632)]} 0 1
[junit4:junit4] 2> 953704 T1906 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438217569556234240)]} 0 0
[junit4:junit4] 2> 953706 T1876 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1438217569556234240)]} 0 6
[junit4:junit4] 2> 953708 T1926 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 11
[junit4:junit4] 2> 953712 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438217569566720000)]} 0 1
[junit4:junit4] 2> 953728 T1909 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438217569574060032)]} 0 3
[junit4:junit4] 2> 953730 T1875 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1438217569574060032)]} 0 12
[junit4:junit4] 2> 953731 T1910 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 16
[junit4:junit4] 2> 953750 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438217569606565888)]} 0 1
[junit4:junit4] 2> 953767 T1928 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438217569621245952)]} 0 1
[junit4:junit4] 2> 953769 T1892 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1438217569621245952)]} 0 6
[junit4:junit4] 2> 953770 T1925 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43]} 0 14
[junit4:junit4] 2> 953775 T1858 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438217569632780288)]} 0 1
[junit4:junit4] 2> 953783 T1907 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438217569638023168)]} 0 1
[junit4:junit4] 2> 953784 T1878 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438217569638023168)]} 0 5
[junit4:junit4] 2> 953795 T1856 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1438217569653751808)]} 0 1
[junit4:junit4] 2> 953808 T1908 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438217569663188992)]} 0 1
[junit4:junit4] 2> 953810 T1874 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1438217569663188992)]} 0 7
[junit4:junit4] 2> 953811 T1891 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 12
[junit4:junit4] 2> 953817 T1857 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438217569677869056)]} 0 1
[junit4:junit4] 2> 953830 T1924 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438217569686257664)]} 0 1
[junit4:junit4] 2> 953833 T1895 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1438217569686257664)]} 0 8
[junit4:junit4] 2> 953835 T1905 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46]} 0 13
[junit4:junit4] 2> 953841 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1438217569701986304)]} 0 2
[junit4:junit4] 2> 953860 T1906 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438217569711423488)]} 0 1
[junit4:junit4] 2> 953861 T1879 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1438217569711423488)]} 0 12
[junit4:junit4] 2> 953863 T1927 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 18
[junit4:junit4] 2> 953872 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438217569735540736)]} 0 1
[junit4:junit4] 2> 953883 T1909 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438217569742880768)]} 0 1
[junit4:junit4] 2> 953884 T1877 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438217569742880768)]} 0 6
[junit4:junit4] 2> 953889 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1438217569752317952)]} 0 1
[junit4:junit4] 2> 953900 T1928 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438217569760706560)]} 0 0
[junit4:junit4] 2> 953902 T1893 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1438217569760706560)]} 0 7
[junit4:junit4] 2> 953904 T1926 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49]} 0 12
[junit4:junit4] 2> 953909 T1858 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438217569773289472)]} 0 1
[junit4:junit4] 2> 953921 T1923 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438217569783775232)]} 0 0
[junit4:junit4] 2> 953923 T1890 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51910/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1438217569783775232)]} 0 5
[junit4:junit4] 2> 953924 T1925 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 10
[junit4:junit4] 2> 953928 T1856 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438217569794260992)]} 0 0
[junit4:junit4] 2> 953937 T1907 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438217569799503872)]} 0 1
[junit4:junit4] 2> 953939 T1875 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438217569799503872)]} 0 7
[junit4:junit4] 2> 953945 T1857 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1438217569811038208)]} 0 1
[junit4:junit4] 2> 953957 T1924 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438217569820475392)]} 0 1
[junit4:junit4] 2> 953958 T1892 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1438217569820475392)]} 0 6
[junit4:junit4] 2> 953961 T1878 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 12
[junit4:junit4] 2> 953966 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1438217569833058304)]} 0 1
[junit4:junit4] 2> 953984 T1908 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438217569839349760)]} 0 8
[junit4:junit4] 2> 953988 T1874 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1438217569839349760)]} 0 17
[junit4:junit4] 2> 953994 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1438217569862418432)]} 0 2
[junit4:junit4] 2> 954013 T1905 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438217569877098496)]} 0 1
[junit4:junit4] 2> 954015 T1879 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438217569877098496)]} 0 8
[junit4:junit4] 2> 954018 T1894 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 15
[junit4:junit4] 2> 954025 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1438217569894924288)]} 0 2
[junit4:junit4] 2> 954039 T1927 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438217569905410048)]} 0 1
[junit4:junit4] 2> 954042 T1891 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1438217569905410048)]} 0 8
[junit4:junit4] 2> 954044 T1876 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 14
[junit4:junit4] 2> 954061 T1858 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1438217569932673024)]} 0 1
[junit4:junit4] 2> 954086 T1928 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438217569950498816)]} 0 5
[junit4:junit4] 2> 954089 T1895 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438217569950498816)]} 0 13
[junit4:junit4] 2> 954091 T1906 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 25
[junit4:junit4] 2> 954098 T1857 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1438217569971470336)]} 0 2
[junit4:junit4] 2> 954114 T1926 C930 P51910 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438217569984053248)]} 0 1
[junit4:junit4] 2> 954117 T1893 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438217569984053248)]} 0 9
[junit4:junit4] 2> 954120 T1910 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 16
[junit4:junit4] 2> 954127 T1859 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1438217570001879040)]} 0 1
[junit4:junit4] 2> 954142 T1909 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1438217570013413376)]} 0 1
[junit4:junit4] 2> 954144 T1877 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51903/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1438217570013413376)]} 0 8
[junit4:junit4] 2> 954147 T1890 C928 P51903 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 14
[junit4:junit4] 2> 954154 T1854 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1438217570030190592)]} 0 1
[junit4:junit4] 2> 954178 T1908 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51900/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1438217570041724928)]} 0 1
[junit4:junit4] 2> 954180 T1875 C932 P51900 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51906/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1438217570041724928)]} 0 16
[junit4:junit4] 2> 954181 T1907 C931 P51906 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 22
[junit4:junit4] 2> 954193 T1855 C929 P51896 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438217570065842176)]} 0 7
[junit4:ju
[...truncated too long message...]
Closer
[junit4:junit4] 2> 998649 T1841 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 998651 T1841 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 998652 T1841 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index;done=false>>]
[junit4:junit4] 2> 998653 T1841 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4/index
[junit4:junit4] 2> 998654 T1841 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4;done=false>>]
[junit4:junit4] 2> 998655 T1841 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371591122702/jetty4
[junit4:junit4] 2> 998666 T1994 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89888595818119180-127.0.0.1:51910_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 998678 T1932 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 998679 T1975 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 998691 T1975 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4:junit4] 2> 998701 T1841 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 998809 T1841 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 998814 T1841 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51893 51893
[junit4:junit4] 2> 999039 T1975 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3601326 name:ZooKeeperConnection Watcher:127.0.0.1:51893/solr got event WatchedEvent state:Disconnected type:None path:null path:null type:None
[junit4:junit4] 2> 999040 T1975 oascc.ConnectionManager.process Client->ZooKeeper status change trigger but we are already closed
[junit4:junit4] 2> 999041 T1841 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51896
[junit4:junit4] 2> !!!! WARNING: best effort to remove /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1371591122702 FAILED !!!!!
[junit4:junit4] 2> 999042 T1841 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 999042 T1841 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51893 51893
[junit4:junit4] 1> "node_name":"127.0.0.1:51900_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51900"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:51903_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51903"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89888595818119171-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:51896_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51896"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89888595818119178-127.0.0.1:51906_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888595818119171-127.0.0.1:51896_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888595818119174-127.0.0.1:51900_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888595818119176-127.0.0.1:51903_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888595818119180-127.0.0.1:51910_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89888595818119171-127.0.0.1:51896_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=20845880F04DF68C -Dtests.slow=true -Dtests.locale=es_AR -Dtests.timezone=America/Adak -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 80.2s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc count on shard1_0 expected:<73> but was:<72>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([20845880F04DF68C:A162D698871296B0]:0)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:209)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:162)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 999103 T1841 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 80226 T1840 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 999981 T1932 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 999982 T1932 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=es_AR, timezone=America/Adak
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=3,free=45675976,total=161132544
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrRequestParserTest, TestPHPSerializedResponseWriter, TestAtomicUpdateErrorCases, TestAddFieldRealTimeGet, SOLR749Test, UpdateRequestProcessorFactoryTest, TestSuggestSpellingConverter, IndexBasedSpellCheckerTest, TestSchemaVersionResource, DocumentBuilderTest, SimpleFacetsTest, SuggesterFSTTest, TestMultiCoreConfBootstrap, TestManagedSchemaFieldResource, ReturnFieldsTest, ExternalFileFieldSortTest, PingRequestHandlerTest, ZkControllerTest, TestReload, TestDocumentBuilder, TestMaxScoreQueryParser, TermVectorComponentTest, BasicDistributedZk2Test, TestMergePolicyConfig, TestFunctionQuery, TestWordDelimiterFilterFactory, SearchHandlerTest, BasicFunctionalityTest, HighlighterTest, TestCSVLoader, TestRandomDVFaceting, TestDefaultSearchFieldResource, TestHashPartitioner, QueryResultKeyTest, JsonLoaderTest, ScriptEngineTest, AliasIntegrationTest, TestRealTimeGet, TestReplicationHandler, BadIndexSchemaTest, TestSolrDeletionPolicy2, MultiTermTest, SuggesterTest, DirectSolrConnectionTest, RequestHandlersTest, SuggesterWFSTTest, TestJmxIntegration, CoreContainerCoreInitFailuresTest, TestPseudoReturnFields, ClusterStateTest, TestBM25SimilarityFactory, LeaderElectionIntegrationTest, SolrPluginUtilsTest, SolrIndexSplitterTest, CurrencyFieldOpenExchangeTest, TestCoreDiscovery, TestReversedWildcardFilterFactory, URLClassifyProcessorTest, DocValuesTest, PolyFieldTest, TestSchemaNameResource, TestSolrQueryParserResource, FastVectorHighlighterTest, TestIndexSearcher, TermVectorComponentDistributedTest, TestConfig, ShardSplitTest]
[junit4:junit4] Completed in 81.34s, 1 test, 1 failure <<< FAILURES!
[...truncated 725 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:392: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:372: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1246: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:890: There were test failures: 298 suites, 1253 tests, 1 failure, 18 ignored (6 assumptions)
Total time: 114 minutes 32 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure