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 2014/03/26 11:10:11 UTC
[JENKINS] Lucene-Solr-4.7-Linux (32bit/jdk1.7.0_51) - Build # 37 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.7-Linux/37/
Java: 32bit/jdk1.7.0_51 -client -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.client.solrj.SolrExampleXMLTest.testUnicode
Error Message:
IOException occured when talking to server at: https://127.0.0.1:36399/solr/collection1
Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: https://127.0.0.1:36399/solr/collection1
at __randomizedtesting.SeedInfo.seed([C599F017F2B3788A:DC55441D5009A97D]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:507)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:199)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:118)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:68)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:54)
at org.apache.solr.client.solrj.SolrExampleTests.testUnicode(SolrExampleTests.java:375)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:744)
Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:143)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:283)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:251)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:197)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:682)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:486)
at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:395)
... 45 more
Build Log:
[...truncated 11810 lines...]
[junit4] Suite: org.apache.solr.client.solrj.SolrExampleXMLTest
[junit4] 2> 94019 T256 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (false)
[junit4] 2> 94019 T256 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/./solrtest-SolrExampleXMLTest-1395828400733
[junit4] 2> 94020 T256 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 94020 T256 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 94023 T256 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 94026 T256 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:36399
[junit4] 2> 94028 T256 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 94028 T256 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 94029 T256 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr
[junit4] 2> 94029 T256 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/'
[junit4] 2> 94067 T256 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/solr.xml
[junit4] 2> 94138 T256 oasc.CorePropertiesLocator.<init> Config-defined core root directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr
[junit4] 2> 94138 T256 oasc.CoreContainer.<init> New CoreContainer 1718046
[junit4] 2> 94139 T256 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/]
[junit4] 2> 94140 T256 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4] 2> 94140 T256 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: null
[junit4] 2> 94141 T256 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4] 2> 94141 T256 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 94141 T256 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 94142 T256 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 94142 T256 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 94142 T256 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 94143 T256 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 94145 T256 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 94146 T256 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 94146 T256 oasc.CoreContainer.load Host Name:
[junit4] 2> 94149 T256 oasc.CorePropertiesLocator.discover Looking for core definitions underneath /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr
[junit4] 2> 94151 T256 oasc.CorePropertiesLocator.discoverUnder Found core collection1 in /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/
[junit4] 2> 94154 T256 oasc.CorePropertiesLocator.discover Found 1 core definitions
[junit4] 2> 94155 T266 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1
[junit4] 2> 94155 T266 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/'
[junit4] 2> 94176 T266 oasc.SolrConfig.initLibs Adding specified lib dirs to ClassLoader
[junit4] 2> 94177 T266 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/extraction/lib (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../contrib/extraction/lib).
[junit4] 2> 94177 T266 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 94177 T266 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/clustering/lib/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../contrib/clustering/lib).
[junit4] 2> 94177 T266 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 94178 T266 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/langid/lib/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../contrib/langid/lib).
[junit4] 2> 94178 T266 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 94178 T266 oasc.SolrResourceLoader.addToClassLoader WARN No files added to classloader from lib: ../../../contrib/velocity/lib (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../contrib/velocity/lib).
[junit4] 2> 94178 T266 oasc.SolrResourceLoader.addToClassLoader WARN Can't find (or read) directory to add to classloader: ../../../dist/ (resolved as: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/../../../dist).
[junit4] 2> 94239 T266 oasu.SolrIndexConfig.<init> IndexWriter infoStream solr logging is enabled
[junit4] 2> 94243 T266 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 94346 T266 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 94347 T266 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 94356 T266 oass.IndexSchema.readSchema [collection1] Schema name=example
[junit4] 2> 95050 T266 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 95062 T266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 95068 T266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 95099 T266 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 95100 T266 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/
[junit4] 2> 95100 T266 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1acb238
[junit4] 2> 95101 T266 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4] 2> 95101 T266 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=static firstSearcher warming in solrconfig.xml}]}
[junit4] 2> 95102 T266 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733
[junit4] 2> 95102 T266 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index/
[junit4] 2> 95103 T266 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index' doesn't exist. Creating new index...
[junit4] 2> 95103 T266 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index
[junit4] 2> 95104 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: current segments file is "null"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@a9198e
[junit4] 2> 95104 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 95105 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 0 msec to checkpoint
[junit4] 2> 95105 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: init: create=true
[junit4] 2> 95105 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]:
[junit4] 2> dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index)
[junit4] 2> index=
[junit4] 2> version=4.7-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_47
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=CREATE
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene46
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@1ccc95b
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 95106 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: now flush at close waitForMerges=true
[junit4] 2> 95106 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: start flush: applyAllDeletes=true
[junit4] 2> 95107 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: index before flush
[junit4] 2> 95107 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 95107 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95107 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 95108 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 95108 T266 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@1b7aeb4 minGen=9223372036854775807 packetCount=0
[junit4] 2> 95108 T266 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: now merge
[junit4] 2> 95109 T266 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: index:
[junit4] 2> 95109 T266 oasu.LoggingInfoStream.message [CMS][coreLoadExecutor-93-thread-1]: no more merges pending; now return
[junit4] 2> 95109 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: waitForMerges
[junit4] 2> 95109 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: waitForMerges done
[junit4] 2> 95110 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: now call final commit()
[junit4] 2> 95110 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: start
[junit4] 2> 95110 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: enter lock
[junit4] 2> 95111 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: now prepare
[junit4] 2> 95111 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: prepareCommit: flush
[junit4] 2> 95111 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: index before flush
[junit4] 2> 95112 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 95112 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95112 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 95112 T266 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@1b7aeb4 minGen=9223372036854775807 packetCount=0
[junit4] 2> 95113 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 95113 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: startCommit(): start
[junit4] 2> 95113 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: startCommit index= changeCount=1
[junit4] 2> 95114 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: done all syncs: []
[junit4] 2> 95114 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: pendingCommit != null
[junit4] 2> 95114 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: wrote segments file "segments_1"
[junit4] 2> 95115 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 95115 T266 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_1,generation=1}
[junit4] 2> 95115 T266 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 95116 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 0 msec to checkpoint
[junit4] 2> 95116 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: commit: done
[junit4] 2> 95116 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: at close:
[junit4] 2> 95117 T266 oasc.SolrCore.initWriters created json: solr.JSONResponseWriter
[junit4] 2> 95117 T266 oasc.SolrCore.initWriters adding lazy queryResponseWriter: solr.VelocityResponseWriter
[junit4] 2> 95117 T266 oasc.SolrCore.initWriters created velocity: solr.VelocityResponseWriter
[junit4] 2> 95118 T266 oasc.SolrCore.initWriters created xslt: solr.XSLTResponseWriter
[junit4] 2> 95118 T266 oasr.XSLTResponseWriter.init xsltCacheLifetimeSeconds=5
[junit4] 2> 95123 T266 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 95124 T266 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 95125 T266 oasc.RequestHandlers.initHandlersFromConfig created /query: solr.SearchHandler
[junit4] 2> 95126 T266 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 95127 T266 oasc.RequestHandlers.initHandlersFromConfig created /browse: solr.SearchHandler
[junit4] 2> 95127 T266 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 95128 T266 oasc.RequestHandlers.initHandlersFromConfig created /update/json: solr.UpdateRequestHandler
[junit4] 2> 95129 T266 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: solr.UpdateRequestHandler
[junit4] 2> 95129 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.extraction.ExtractingRequestHandler
[junit4] 2> 95130 T266 oasc.RequestHandlers.initHandlersFromConfig created /update/extract: solr.extraction.ExtractingRequestHandler
[junit4] 2> 95130 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.FieldAnalysisRequestHandler
[junit4] 2> 95130 T266 oasc.RequestHandlers.initHandlersFromConfig created /analysis/field: solr.FieldAnalysisRequestHandler
[junit4] 2> 95131 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.DocumentAnalysisRequestHandler
[junit4] 2> 95131 T266 oasc.RequestHandlers.initHandlersFromConfig created /analysis/document: solr.DocumentAnalysisRequestHandler
[junit4] 2> 95132 T266 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 95133 T266 oasc.RequestHandlers.initHandlersFromConfig created /admin/ping: solr.PingRequestHandler
[junit4] 2> 95133 T266 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4] 2> 95134 T266 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 95135 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 95135 T266 oasc.RequestHandlers.initHandlersFromConfig created /spell: solr.SearchHandler
[junit4] 2> 95135 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 95136 T266 oasc.RequestHandlers.initHandlersFromConfig created /suggest: solr.SearchHandler
[junit4] 2> 95136 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 95136 T266 oasc.RequestHandlers.initHandlersFromConfig created /tvrh: solr.SearchHandler
[junit4] 2> 95137 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 95137 T266 oasc.RequestHandlers.initHandlersFromConfig created /terms: solr.SearchHandler
[junit4] 2> 95137 T266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.SearchHandler
[junit4] 2> 95138 T266 oasc.RequestHandlers.initHandlersFromConfig created /elevate: solr.SearchHandler
[junit4] 2> 95142 T266 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 95143 T266 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 95145 T266 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 95154 T266 oasu.CommitTracker.<init> Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 95154 T266 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 95156 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: current segments file is "segments_1"; deletionPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper@a9198e
[junit4] 2> 95156 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: init: load commit "segments_1"
[junit4] 2> 95157 T266 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_1,generation=1}
[junit4] 2> 95157 T266 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 95157 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 95157 T266 oasu.LoggingInfoStream.message [IFD][coreLoadExecutor-93-thread-1]: 0 msec to checkpoint
[junit4] 2> 95158 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: init: create=false
[junit4] 2> 95158 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]:
[junit4] 2> dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index)
[junit4] 2> index=
[junit4] 2> version=4.7-SNAPSHOT
[junit4] 2> matchVersion=LUCENE_47
[junit4] 2> analyzer=null
[junit4] 2> ramBufferSizeMB=100.0
[junit4] 2> maxBufferedDocs=-1
[junit4] 2> maxBufferedDeleteTerms=-1
[junit4] 2> mergedSegmentWarmer=null
[junit4] 2> readerTermsIndexDivisor=1
[junit4] 2> termIndexInterval=32
[junit4] 2> delPolicy=org.apache.solr.core.IndexDeletionPolicyWrapper
[junit4] 2> commit=null
[junit4] 2> openMode=APPEND
[junit4] 2> similarity=org.apache.lucene.search.similarities.DefaultSimilarity
[junit4] 2> mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
[junit4] 2> default WRITE_LOCK_TIMEOUT=1000
[junit4] 2> writeLockTimeout=1000
[junit4] 2> codec=Lucene46
[junit4] 2> infoStream=org.apache.solr.update.LoggingInfoStream
[junit4] 2> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@d75341
[junit4] 2> readerPooling=false
[junit4] 2> perThreadHardLimitMB=1945
[junit4] 2> useCompoundFile=false
[junit4] 2>
[junit4] 2> 95159 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: flush at getReader
[junit4] 2> 95159 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 startFullFlush
[junit4] 2> 95159 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95160 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: apply all deletes during flush
[junit4] 2> 95160 T266 oasu.LoggingInfoStream.message [BD][coreLoadExecutor-93-thread-1]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=0
[junit4] 2> 95160 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 95161 T266 oasu.LoggingInfoStream.message [DW][coreLoadExecutor-93-thread-1]: coreLoadExecutor-93-thread-1 finishFullFlush success=true
[junit4] 2> 95161 T266 oasu.LoggingInfoStream.message [IW][coreLoadExecutor-93-thread-1]: getReader took 2 msec
[junit4] 2> 95161 T266 oass.SolrIndexSearcher.<init> Opening Searcher@173640c[collection1] main
[junit4] 2> 95162 T266 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4] 2> 95162 T266 oass.DirectSolrSpellChecker.init init: {name=default,field=text,classname=solr.DirectSolrSpellChecker,distanceMeasure=internal,accuracy=0.5,maxEdits=2,minPrefix=1,maxInspections=5,minQueryLength=4,maxQueryFrequency=0.01}
[junit4] 2> 95162 T266 oashc.SpellCheckComponent.inform No queryConverter defined, using default converter
[junit4] 2> 95163 T266 oashc.SuggestComponent.inform Initializing SuggestComponent
[junit4] 2> 95163 T266 oasss.SolrSuggester.init init: {name=mySuggester,lookupImpl=FuzzyLookupFactory,dictionaryImpl=DocumentDictionaryFactory,field=cat,weightField=price,suggestAnalyzerFieldType=string}
[junit4] 2> 95164 T266 oasss.SolrSuggester.init Dictionary loaded with params: {name=mySuggester,lookupImpl=FuzzyLookupFactory,dictionaryImpl=DocumentDictionaryFactory,field=cat,weightField=price,suggestAnalyzerFieldType=string}
[junit4] 2> 95164 T266 oashc.QueryElevationComponent.inform Loading QueryElevation from: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/example/solr/collection1/conf/elevate.xml
[junit4] 2> 95185 T266 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 95185 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@173640c[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> ASYNC NEW_CORE C47 name=collection1 org.apache.solr.core.SolrCore@19907f7
[junit4] 2> 95186 T267 C47 oasc.SolrCore.execute [collection1] webapp=null path=null params={distrib=false&event=firstSearcher&q=static+firstSearcher+warming+in+solrconfig.xml} hits=0 status=0 QTime=1
[junit4] 2> 95187 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95187 T267 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: default
[junit4] 2> 95187 T267 oashc.SpellCheckComponent$SpellCheckerListener.newSearcher Loading spell index for spellchecker: wordbreak
[junit4] 2> 95187 T267 oashc.SuggestComponent$SuggesterListener.newSearcher Loading suggester index for: mySuggester
[junit4] 2> 95187 T267 oasss.SolrSuggester.reload reload()
[junit4] 2> 95187 T267 oasss.SolrSuggester.build build()
[junit4] 2> 95191 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@173640c[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 95196 T266 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 95196 T256 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0
[junit4] 2> 95197 T256 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 95197 T256 oas.SolrJettyTestBase.createJetty Jetty Assigned Port#36399
[junit4] 2> 95202 T256 oas.SolrTestCaseJ4.setUp ###Starting testGetEmptyResults
[junit4] 2> 95293 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95293 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 95293 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95294 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: flush at getReader
[junit4] 2> 95294 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95294 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95295 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263: flush naked frozen global deletes
[junit4] 2> 95295 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: push deletes 1 deleted queries bytesUsed=32 delGen=2 packetCount=1 totBytesUsed=32
[junit4] 2> 95295 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: flush: push buffered updates: 1 deleted queries bytesUsed=32
[junit4] 2> 95296 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95296 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=1
[junit4] 2> 95296 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95297 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: return reader version=1 reader=StandardDirectoryReader(segments_1:1:nrt)
[junit4] 2> 95297 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95297 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: getReader took 3 msec
[junit4] 2> 95298 T263 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {deleteByQuery=*:* (-1463632162461843456)} 0 6
[junit4] 2> 95302 T265 C47 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95303 T265 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95303 T265 C47 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4] 2> 95304 T265 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95304 T265 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 95305 T265 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95305 T265 C47 oass.SolrIndexSearcher.<init> Opening Searcher@27ebb8[collection1] main
[junit4] 2> 95306 T265 C47 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95306 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@27ebb8[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 95306 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95310 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@27ebb8[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 95311 T265 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 9
[junit4] 2> 95316 T262 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[id1 (1463632162484912128)]} 0 2
[junit4] 2> 95319 T264 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[id2 (1463632162490155008)]} 0 0
[junit4] 2> 95323 T263 C47 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95324 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: start
[junit4] 2> 95324 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: enter lock
[junit4] 2> 95325 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: now prepare
[junit4] 2> 95325 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: prepareCommit: flush
[junit4] 2> 95325 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: index before flush
[junit4] 2> 95325 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95326 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=2 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95326 T263 C47 oasu.LoggingInfoStream.message [DWFC][qtp31053315-263]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0 1 deleted terms (unique count=1) bytesUsed=139, segment=_0, aborting=false, numDocsInRAM=2, deleteQueue=DWDQ: [ generation: 2 ]]
[junit4] 2> 95326 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flush postings as segment _0 numDocs=2
[junit4] 2> 95328 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: new segment has 0 deleted docs
[junit4] 2> 95328 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: new segment has no vectors; norms; no docValues; prox; freqs
[junit4] 2> 95328 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushedFiles=[_0.nvd, _0.fdt, _0_Lucene41_0.tip, _0.fdx, _0_Lucene41_0.doc, _0.nvm, _0_Lucene41_0.pos, _0_Lucene41_0.tim, _0.fnm]
[junit4] 2> 95328 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushed codec=Lucene46
[junit4] 2> 95329 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushed: segment=_0 ramUsed=0.08 MB newFlushedSize(includes docstores)=0.002 MB docs/MB=1,284.233
[junit4] 2> 95329 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: publishFlushedSegment seg-private updates=null
[junit4] 2> 95329 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: publishFlushedSegment
[junit4] 2> 95330 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: push deletes 2 deleted terms (unique count=2) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
[junit4] 2> 95330 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: publish sets newSegment delGen=5 seg=_0(4.7):C2
[junit4] 2> 95330 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "_0(4.7):C2" [1 segments ; isCommit = false]
[junit4] 2> 95331 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 0 msec to checkpoint
[junit4] 2> 95331 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95331 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes: infos=[_0(4.7):C2] packetCount=1
[junit4] 2> 95332 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes took 1 msec
[junit4] 2> 95332 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=6 packetCount=1
[junit4] 2> 95332 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95333 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95333 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: findMerges: 1 segments
[junit4] 2> 95333 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: seg=_0(4.7):C2 size=0.001 MB [floored]
[junit4] 2> 95334 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 95334 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: now merge
[junit4] 2> 95335 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: index: _0(4.7):C2
[junit4] 2> 95335 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: no more merges pending; now return
[junit4] 2> 95335 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: startCommit(): start
[junit4] 2> 95335 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: startCommit index=_0(4.7):C2 changeCount=3
[junit4] 2> 95336 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: done all syncs: [_0.nvd, _0.si, _0.fdt, _0_Lucene41_0.tip, _0.fdx, _0_Lucene41_0.doc, _0.nvm, _0_Lucene41_0.pos, _0_Lucene41_0.tim, _0.fnm]
[junit4] 2> 95336 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: pendingCommit != null
[junit4] 2> 95337 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: wrote segments file "segments_2"
[junit4] 2> 95337 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "_0(4.7):C2" [1 segments ; isCommit = true]
[junit4] 2> 95338 T263 C47 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_2,generation=2}
[junit4] 2> 95338 T263 C47 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 95338 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: deleteCommits: now decRef commit "segments_1"
[junit4] 2> 95339 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: delete "segments_1"
[junit4] 2> 95339 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 2 msec to checkpoint
[junit4] 2> 95339 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: done
[junit4] 2> 95340 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95340 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 95340 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: flush at getReader
[junit4] 2> 95341 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95341 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95341 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95341 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes: no deletes; skipping
[junit4] 2> 95342 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=6 packetCount=0
[junit4] 2> 95343 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: return reader version=3 reader=StandardDirectoryReader(segments_2:3:nrt _0(4.7):C2)
[junit4] 2> 95343 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95344 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: getReader took 4 msec
[junit4] 2> 95344 T263 C47 oass.SolrIndexSearcher.<init> Opening Searcher@23d80b[collection1] main
[junit4] 2> 95344 T263 C47 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95344 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@23d80b[collection1] main{StandardDirectoryReader(segments_2:3:nrt _0(4.7):C2)}
[junit4] 2> 95345 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95348 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23d80b[collection1] main{StandardDirectoryReader(segments_2:3:nrt _0(4.7):C2)}
[junit4] 2> 95349 T263 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 26
[junit4] 2> 95352 T265 C47 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={fl=foofoofoo&q=*:*&version=2.2&wt=xml} hits=2 status=0 QTime=0
[junit4] 2> 95353 T256 oas.SolrTestCaseJ4.tearDown ###Ending testGetEmptyResults
[junit4] 2> 95363 T256 oas.SolrTestCaseJ4.setUp ###Starting testAddDelete
[junit4] 2> 95366 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95366 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 95367 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95367 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: flush at getReader
[junit4] 2> 95367 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 startFullFlush
[junit4] 2> 95368 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95368 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262: flush naked frozen global deletes
[junit4] 2> 95368 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: push deletes 1 deleted queries bytesUsed=32 delGen=8 packetCount=1 totBytesUsed=32
[junit4] 2> 95369 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: flush: push buffered updates: 1 deleted queries bytesUsed=32
[junit4] 2> 95369 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: apply all deletes during flush
[junit4] 2> 95369 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: applyDeletes: infos=[_0(4.7):C2] packetCount=1
[junit4] 2> 95370 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: seg=_0(4.7):C2 segGen=6 coalesced deletes=[CoalescedUpdates(termSets=1,queries=1,numericUpdates=0)] newDelCount=2 100% deleted
[junit4] 2> 95371 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: applyDeletes took 2 msec
[junit4] 2> 95371 T262 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: now checkpoint "_0(4.7):C2/2" [1 segments ; isCommit = false]
[junit4] 2> 95371 T262 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: 0 msec to checkpoint
[junit4] 2> 95372 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: drop 100% deleted segments: _0(4.7):C2/2
[junit4] 2> 95372 T262 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 95373 T262 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: 0 msec to checkpoint
[junit4] 2> 95373 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=1
[junit4] 2> 95374 T262 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95378 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: return reader version=5 reader=StandardDirectoryReader(segments_2:5:nrt)
[junit4] 2> 95379 T262 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 finishFullFlush success=true
[junit4] 2> 95379 T262 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: getReader took 12 msec
[junit4] 2> 95380 T262 C47 oass.SolrIndexSearcher.<init> Opening Searcher@11c3d6b[collection1] realtime
[junit4] 2> 95380 T262 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {deleteByQuery=*:* (-1463632162538389504)} 0 15
[junit4] 2> 95384 T264 C47 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[0 & 222 (1463632162558312448)]} 0 1
[junit4] 2> 95391 T263 C47 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95391 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: start
[junit4] 2> 95392 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: enter lock
[junit4] 2> 95392 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: now prepare
[junit4] 2> 95393 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: prepareCommit: flush
[junit4] 2> 95393 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: index before flush
[junit4] 2> 95393 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95394 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95394 T263 C47 oasu.LoggingInfoStream.message [DWFC][qtp31053315-263]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_1, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 5 ]]
[junit4] 2> 95395 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flush postings as segment _1 numDocs=1
[junit4] 2> 95396 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: new segment has 0 deleted docs
[junit4] 2> 95396 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 95397 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushedFiles=[_1_Lucene41_0.doc, _1.fdt, _1_Lucene41_0.tim, _1.fnm, _1_Lucene41_0.tip, _1.fdx]
[junit4] 2> 95397 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushed codec=Lucene46
[junit4] 2> 95398 T263 C47 oasu.LoggingInfoStream.message [DWPT][qtp31053315-263]: flushed: segment=_1 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,736.053
[junit4] 2> 95398 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: publishFlushedSegment seg-private updates=null
[junit4] 2> 95399 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: publishFlushedSegment
[junit4] 2> 95399 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=10 packetCount=1 totBytesUsed=1024
[junit4] 2> 95400 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: publish sets newSegment delGen=11 seg=_1(4.7):C1
[junit4] 2> 95400 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "_1(4.7):C1" [1 segments ; isCommit = false]
[junit4] 2> 95401 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 0 msec to checkpoint
[junit4] 2> 95401 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95402 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes: infos=[_1(4.7):C1] packetCount=1
[junit4] 2> 95402 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes took 0 msec
[junit4] 2> 95402 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=12 packetCount=1
[junit4] 2> 95403 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95403 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95404 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: findMerges: 1 segments
[junit4] 2> 95404 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: seg=_1(4.7):C1 size=0.000 MB [floored]
[junit4] 2> 95405 T263 C47 oasu.LoggingInfoStream.message [TMP][qtp31053315-263]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 95405 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: now merge
[junit4] 2> 95406 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: index: _1(4.7):C1
[junit4] 2> 95406 T263 C47 oasu.LoggingInfoStream.message [CMS][qtp31053315-263]: no more merges pending; now return
[junit4] 2> 95406 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: startCommit(): start
[junit4] 2> 95407 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: startCommit index=_1(4.7):C1 changeCount=8
[junit4] 2> 95407 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: done all syncs: [_1.si, _1.fdt, _1_Lucene41_0.doc, _1_Lucene41_0.tim, _1.fnm, _1_Lucene41_0.tip, _1.fdx]
[junit4] 2> 95408 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: pendingCommit != null
[junit4] 2> 95409 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: wrote segments file "segments_3"
[junit4] 2> 95409 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "_1(4.7):C1" [1 segments ; isCommit = true]
[junit4] 2> 95409 T263 C47 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_2,generation=2}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_3,generation=3}
[junit4] 2> 95410 T263 C47 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4] 2> 95410 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: deleteCommits: now decRef commit "segments_2"
[junit4] 2> 95411 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: delete "segments_2"
[junit4] 2> 95411 T263 C47 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 1 msec to checkpoint
[junit4] 2> 95411 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: commit: done
[junit4] 2> 95411 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95412 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 95412 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: flush at getReader
[junit4] 2> 95412 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95412 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95413 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95413 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes: no deletes; skipping
[junit4] 2> 95413 T263 C47 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=12 packetCount=0
[junit4] 2> 95414 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: return reader version=7 reader=StandardDirectoryReader(segments_3:7:nrt _1(4.7):C1)
[junit4] 2> 95414 T263 C47 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95415 T263 C47 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: getReader took 3 msec
[junit4] 2> 95415 T263 C47 oass.SolrIndexSearcher.<init> Opening Searcher@1e4bfc6[collection1] main
[junit4] 2> 95416 T263 C47 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95416 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1e4bfc6[collection1] main{StandardDirectoryReader(segments_3:7:nrt _1(4.7):C1)}
[junit4] 2> 95416 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95438 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e4bfc6[collection1] main{StandardDirectoryReader(segments_3:7:nrt _1(4.7):C1)}
[junit4] 2> 95439 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.nvd"
[junit4] 2> 95439 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.si"
[junit4] 2> 95439 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.fdt"
[junit4] 2> 95440 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.tip"
[junit4] 2> 95440 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.fdx"
[junit4] 2> 95440 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.doc"
[junit4] 2> 95440 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.nvm"
[junit4] 2> 95441 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.pos"
[junit4] 2> 95441 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0_Lucene41_0.tim"
[junit4] 2> 95441 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_0.fnm"
[junit4] 2> ASYNC NEW_CORE C48 name=collection1 org.apache.solr.core.SolrCore@19907f7
[junit4] 2> 95442 T263 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 51
[junit4] 2> 95445 T265 C48 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&version=2.2&wt=xml} hits=1 status=0 QTime=0
[junit4] 2> 95449 T262 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {delete=[0 & 222 (-1463632162626469888)]} 0 1
[junit4] 2> 95453 T264 C48 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95454 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95454 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: start
[junit4] 2> 95455 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: enter lock
[junit4] 2> 95455 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: now prepare
[junit4] 2> 95456 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: prepareCommit: flush
[junit4] 2> 95456 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: index before flush _1(4.7):C1
[junit4] 2> 95456 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: qtp31053315-264 startFullFlush
[junit4] 2> 95457 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95457 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: qtp31053315-264: flush naked frozen global deletes
[junit4] 2> 95458 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=14 packetCount=1 totBytesUsed=1024
[junit4] 2> 95458 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: flush: push buffered updates: 1 deleted terms (unique count=1) bytesUsed=1024
[junit4] 2> 95459 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: apply all deletes during flush
[junit4] 2> 95459 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: applyDeletes: infos=[_1(4.7):C1] packetCount=1
[junit4] 2> 95459 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: seg=_1(4.7):C1 segGen=12 coalesced deletes=[CoalescedUpdates(termSets=1,queries=0,numericUpdates=0)] newDelCount=1 100% deleted
[junit4] 2> 95460 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: applyDeletes took 1 msec
[junit4] 2> 95460 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: now checkpoint "_1(4.7):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 95461 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: 0 msec to checkpoint
[junit4] 2> 95461 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: drop 100% deleted segments: _1(4.7):C1/1
[junit4] 2> 95462 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 95462 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: 0 msec to checkpoint
[junit4] 2> 95463 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=1
[junit4] 2> 95463 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95463 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: qtp31053315-264 finishFullFlush success=true
[junit4] 2> 95464 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: startCommit(): start
[junit4] 2> 95464 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: startCommit index= changeCount=11
[junit4] 2> 95465 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: done all syncs: []
[junit4] 2> 95465 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: pendingCommit != null
[junit4] 2> 95466 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: wrote segments file "segments_4"
[junit4] 2> 95466 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 95466 T264 C48 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_3,generation=3}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_4,generation=4}
[junit4] 2> 95467 T264 C48 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4] 2> 95467 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: deleteCommits: now decRef commit "segments_3"
[junit4] 2> 95468 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: delete "segments_3"
[junit4] 2> 95468 T264 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-264]: 2 msec to checkpoint
[junit4] 2> 95468 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: commit: done
[junit4] 2> 95469 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95469 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 95470 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: flush at getReader
[junit4] 2> 95470 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: qtp31053315-264 startFullFlush
[junit4] 2> 95471 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95471 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: apply all deletes during flush
[junit4] 2> 95471 T264 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-264]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=0
[junit4] 2> 95472 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: return reader version=9 reader=StandardDirectoryReader(segments_4:9:nrt)
[junit4] 2> 95472 T264 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-264]: qtp31053315-264 finishFullFlush success=true
[junit4] 2> 95473 T264 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-264]: getReader took 3 msec
[junit4] 2> 95473 T264 C48 oass.SolrIndexSearcher.<init> Opening Searcher@bcfb3b[collection1] main
[junit4] 2> 95474 T264 C48 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95474 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@bcfb3b[collection1] main{StandardDirectoryReader(segments_4:9:nrt)}
[junit4] 2> 95474 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95479 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bcfb3b[collection1] main{StandardDirectoryReader(segments_4:9:nrt)}
[junit4] 2> 95481 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1.si"
[junit4] 2> 95482 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1.fdt"
[junit4] 2> 95482 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1_Lucene41_0.doc"
[junit4] 2> 95483 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1_Lucene41_0.tim"
[junit4] 2> 95483 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1.fnm"
[junit4] 2> 95483 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1_Lucene41_0.tip"
[junit4] 2> 95484 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_1.fdx"
[junit4] 2> 95484 T264 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 31
[junit4] 2> 95488 T263 C48 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&version=2.2&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 95492 T265 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[0 & 222 (1463632162670510080)]} 0 1
[junit4] 2> 95496 T262 C48 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95497 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: start
[junit4] 2> 95498 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: enter lock
[junit4] 2> 95498 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: now prepare
[junit4] 2> 95499 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: prepareCommit: flush
[junit4] 2> 95499 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: index before flush
[junit4] 2> 95499 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 startFullFlush
[junit4] 2> 95499 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=1 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95500 T262 C48 oasu.LoggingInfoStream.message [DWFC][qtp31053315-262]: addFlushableState DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_2, aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 9 ]]
[junit4] 2> 95500 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: flush postings as segment _2 numDocs=1
[junit4] 2> 95501 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: new segment has 0 deleted docs
[junit4] 2> 95501 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: new segment has no vectors; no norms; no docValues; no prox; no freqs
[junit4] 2> 95502 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: flushedFiles=[_2_Lucene41_0.doc, _2.fdt, _2.fdx, _2_Lucene41_0.tim, _2_Lucene41_0.tip, _2.fnm]
[junit4] 2> 95502 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: flushed codec=Lucene46
[junit4] 2> 95502 T262 C48 oasu.LoggingInfoStream.message [DWPT][qtp31053315-262]: flushed: segment=_2 ramUsed=0.063 MB newFlushedSize(includes docstores)=0.001 MB docs/MB=1,736.053
[junit4] 2> 95503 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: publishFlushedSegment seg-private updates=null
[junit4] 2> 95503 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: publishFlushedSegment
[junit4] 2> 95503 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: push deletes 1 deleted terms (unique count=1) bytesUsed=1024 delGen=17 packetCount=1 totBytesUsed=1024
[junit4] 2> 95504 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: publish sets newSegment delGen=18 seg=_2(4.7):C1
[junit4] 2> 95504 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: now checkpoint "_2(4.7):C1" [1 segments ; isCommit = false]
[junit4] 2> 95504 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: 0 msec to checkpoint
[junit4] 2> 95504 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: apply all deletes during flush
[junit4] 2> 95505 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: applyDeletes: infos=[_2(4.7):C1] packetCount=1
[junit4] 2> 95505 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: applyDeletes took 0 msec
[junit4] 2> 95505 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=19 packetCount=1
[junit4] 2> 95506 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95506 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 finishFullFlush success=true
[junit4] 2> 95506 T262 C48 oasu.LoggingInfoStream.message [TMP][qtp31053315-262]: findMerges: 1 segments
[junit4] 2> 95507 T262 C48 oasu.LoggingInfoStream.message [TMP][qtp31053315-262]: seg=_2(4.7):C1 size=0.000 MB [floored]
[junit4] 2> 95507 T262 C48 oasu.LoggingInfoStream.message [TMP][qtp31053315-262]: allowedSegmentCount=1 vs count=1 (eligible count=1) tooBigCount=0
[junit4] 2> 95507 T262 C48 oasu.LoggingInfoStream.message [CMS][qtp31053315-262]: now merge
[junit4] 2> 95508 T262 C48 oasu.LoggingInfoStream.message [CMS][qtp31053315-262]: index: _2(4.7):C1
[junit4] 2> 95508 T262 C48 oasu.LoggingInfoStream.message [CMS][qtp31053315-262]: no more merges pending; now return
[junit4] 2> 95509 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: startCommit(): start
[junit4] 2> 95509 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: startCommit index=_2(4.7):C1 changeCount=14
[junit4] 2> 95510 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: done all syncs: [_2_Lucene41_0.doc, _2.fdt, _2.fdx, _2.si, _2_Lucene41_0.tim, _2_Lucene41_0.tip, _2.fnm]
[junit4] 2> 95510 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: pendingCommit != null
[junit4] 2> 95510 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: wrote segments file "segments_5"
[junit4] 2> 95510 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: now checkpoint "_2(4.7):C1" [1 segments ; isCommit = true]
[junit4] 2> 95511 T262 C48 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_4,generation=4}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_5,generation=5}
[junit4] 2> 95511 T262 C48 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4] 2> 95511 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: deleteCommits: now decRef commit "segments_4"
[junit4] 2> 95512 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: delete "segments_4"
[junit4] 2> 95512 T262 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-262]: 1 msec to checkpoint
[junit4] 2> 95512 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: done
[junit4] 2> 95513 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95513 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: nrtIsCurrent: infoVersion matches: false; DW changes: false; BD changes: false
[junit4] 2> 95513 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: flush at getReader
[junit4] 2> 95514 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 startFullFlush
[junit4] 2> 95514 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95514 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: apply all deletes during flush
[junit4] 2> 95514 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: applyDeletes: no deletes; skipping
[junit4] 2> 95515 T262 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-262]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=19 packetCount=0
[junit4] 2> 95515 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: return reader version=11 reader=StandardDirectoryReader(segments_5:11:nrt _2(4.7):C1)
[junit4] 2> 95516 T262 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-262]: qtp31053315-262 finishFullFlush success=true
[junit4] 2> 95516 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: getReader took 3 msec
[junit4] 2> 95516 T262 C48 oass.SolrIndexSearcher.<init> Opening Searcher@15f255d[collection1] main
[junit4] 2> 95517 T262 C48 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95517 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@15f255d[collection1] main{StandardDirectoryReader(segments_5:11:nrt _2(4.7):C1)}
[junit4] 2> 95517 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95521 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15f255d[collection1] main{StandardDirectoryReader(segments_5:11:nrt _2(4.7):C1)}
[junit4] 2> 95521 T262 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 25
[junit4] 2> 95525 T264 C48 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&version=2.2&wt=xml} hits=1 status=0 QTime=1
[junit4] 2> 95528 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95529 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: nrtIsCurrent: infoVersion matches: true; DW changes: true; BD changes: false
[junit4] 2> 95529 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95530 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: flush at getReader
[junit4] 2> 95530 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 startFullFlush
[junit4] 2> 95530 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: anyChanges? numDocsInRam=0 deletes=true hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95531 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263: flush naked frozen global deletes
[junit4] 2> 95531 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: push deletes 1 deleted queries bytesUsed=32 delGen=21 packetCount=1 totBytesUsed=32
[junit4] 2> 95531 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: flush: push buffered updates: 1 deleted queries bytesUsed=32
[junit4] 2> 95532 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: apply all deletes during flush
[junit4] 2> 95532 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes: infos=[_2(4.7):C1] packetCount=1
[junit4] 2> 95533 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: seg=_2(4.7):C1 segGen=19 coalesced deletes=[CoalescedUpdates(termSets=1,queries=1,numericUpdates=0)] newDelCount=1 100% deleted
[junit4] 2> 95534 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: applyDeletes took 2 msec
[junit4] 2> 95534 T263 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "_2(4.7):C1/1" [1 segments ; isCommit = false]
[junit4] 2> 95535 T263 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 0 msec to checkpoint
[junit4] 2> 95535 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: drop 100% deleted segments: _2(4.7):C1/1
[junit4] 2> 95535 T263 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: now checkpoint "" [0 segments ; isCommit = false]
[junit4] 2> 95536 T263 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-263]: 0 msec to checkpoint
[junit4] 2> 95536 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=1
[junit4] 2> 95537 T263 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-263]: pruneDeletes: prune 1 packets; 0 packets remain
[junit4] 2> 95537 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: return reader version=13 reader=StandardDirectoryReader(segments_5:13:nrt)
[junit4] 2> 95537 T263 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-263]: qtp31053315-263 finishFullFlush success=true
[junit4] 2> 95538 T263 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-263]: getReader took 8 msec
[junit4] 2> 95538 T263 C48 oass.SolrIndexSearcher.<init> Opening Searcher@1a15229[collection1] realtime
[junit4] 2> 95538 T263 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {deleteByQuery=id:"0\ \&\ 222" (-1463632162709307392)} 0 10
[junit4] 2> 95542 T265 C48 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95543 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: start
[junit4] 2> 95543 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: enter lock
[junit4] 2> 95544 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: now prepare
[junit4] 2> 95544 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: prepareCommit: flush
[junit4] 2> 95544 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: index before flush
[junit4] 2> 95545 T265 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: qtp31053315-265 startFullFlush
[junit4] 2> 95545 T265 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95546 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: apply all deletes during flush
[junit4] 2> 95546 T265 C48 oasu.LoggingInfoStream.message [BD][qtp31053315-265]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=9223372036854775807 packetCount=0
[junit4] 2> 95546 T265 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: qtp31053315-265 finishFullFlush success=true
[junit4] 2> 95547 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: startCommit(): start
[junit4] 2> 95547 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: startCommit index= changeCount=17
[junit4] 2> 95548 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: done all syncs: []
[junit4] 2> 95548 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: pendingCommit != null
[junit4] 2> 95548 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: wrote segments file "segments_6"
[junit4] 2> 95549 T265 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-265]: now checkpoint "" [0 segments ; isCommit = true]
[junit4] 2> 95549 T265 C48 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_5,generation=5}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_6,generation=6}
[junit4] 2> 95550 T265 C48 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4] 2> 95550 T265 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-265]: deleteCommits: now decRef commit "segments_5"
[junit4] 2> 95551 T265 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-265]: delete "segments_5"
[junit4] 2> 95551 T265 C48 oasu.LoggingInfoStream.message [IFD][qtp31053315-265]: 2 msec to checkpoint
[junit4] 2> 95551 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: commit: done
[junit4] 2> 95552 T265 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95552 T265 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-265]: nrtIsCurrent: infoVersion matches: true; DW changes: false; BD changes: false
[junit4] 2> 95553 T265 C48 oasu.LoggingInfoStream.message [DW][qtp31053315-265]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 95553 T265 C48 oass.SolrIndexSearcher.<init> Opening Searcher@e568e3[collection1] main
[junit4] 2> 95554 T265 C48 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 95554 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@e568e3[collection1] main{StandardDirectoryReader(segments_5:13:nrt)}
[junit4] 2> 95554 T267 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4] 2> 95558 T267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e568e3[collection1] main{StandardDirectoryReader(segments_5:13:nrt)}
[junit4] 2> 95558 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2_Lucene41_0.doc"
[junit4] 2> 95558 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2.fdt"
[junit4] 2> 95559 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2.fdx"
[junit4] 2> 95559 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2.si"
[junit4] 2> 95559 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2_Lucene41_0.tim"
[junit4] 2> 95559 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2_Lucene41_0.tip"
[junit4] 2> 95560 T267 oasu.LoggingInfoStream.message [IFD][searcherExecutor-94-thread-1]: delete "_2.fnm"
[junit4] 2> 95560 T265 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={softCommit=false&waitSearcher=true&commit=true&version=2.2&wt=xml} {commit=} 0 18
[junit4] 2> 95563 T262 C48 oasc.SolrCore.execute [collection1] webapp=/solr path=/select params={q=*:*&version=2.2&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 95567 T264 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[0 & 222 (1463632162749153280)]} 0 1
[junit4] 2> 95570 T263 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[1 & 222 (1463632162753347584)]} 0 0
[junit4] 2> 95573 T265 C48 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={version=2.2&wt=xml} {add=[2 & 222 (1463632162756493312)]} 0 0
[junit4] 2> 95577 T262 C48 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 95577 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: start
[junit4] 2> 95578 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: enter lock
[junit4] 2> 95578 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: commit: now prepare
[junit4] 2> 95578 T262 C48 oasu.LoggingInfoStream.message [IW][qtp31053315-262]: prepareCommit: flush
[junit4] 2> 95578 T262 C48 oasu.LoggingInfoStream.me
[...truncated too long message...]
/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_1l,generation=57}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1c64326 lockFactory=NativeFSLockFactory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index),segFN=segments_1m,generation=58}
[junit4] 2> 302114 T256 C56 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 58
[junit4] 2> 302115 T256 C56 oasu.LoggingInfoStream.message [IFD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: deleteCommits: now decRef commit "segments_1l"
[junit4] 2> 302115 T256 C56 oasu.LoggingInfoStream.message [IFD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: delete "segments_1l"
[junit4] 2> 302115 T256 C56 oasu.LoggingInfoStream.message [IFD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: 1 msec to checkpoint
[junit4] 2> 302115 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: done
[junit4] 2> 302116 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: now flush at close waitForMerges=true
[junit4] 2> 302116 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: start flush: applyAllDeletes=true
[junit4] 2> 302117 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: index before flush _14(4.7):C1 _15(4.7):C1
[junit4] 2> 302117 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker startFullFlush
[junit4] 2> 302117 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 302117 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker finishFullFlush success=true
[junit4] 2> 302118 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: apply all deletes during flush
[junit4] 2> 302118 T256 C56 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 302118 T256 C56 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=243 packetCount=0
[junit4] 2> 302119 T256 C56 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: now merge
[junit4] 2> 302119 T256 C56 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: index: _14(4.7):C1 _15(4.7):C1
[junit4] 2> 302119 T256 C56 oasu.LoggingInfoStream.message [CMS][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: no more merges pending; now return
[junit4] 2> 302120 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: waitForMerges
[junit4] 2> 302120 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: waitForMerges done
[junit4] 2> 302120 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: now call final commit()
[junit4] 2> 302120 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: start
[junit4] 2> 302121 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: enter lock
[junit4] 2> 302121 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: now prepare
[junit4] 2> 302121 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: prepareCommit: flush
[junit4] 2> 302121 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: index before flush _14(4.7):C1 _15(4.7):C1
[junit4] 2> 302122 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker startFullFlush
[junit4] 2> 302122 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: anyChanges? numDocsInRam=0 deletes=false hasTickets:false pendingChangesInFullFlush: false
[junit4] 2> 302122 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: apply all deletes during flush
[junit4] 2> 302123 T256 C56 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: applyDeletes: no deletes; skipping
[junit4] 2> 302123 T256 C56 oasu.LoggingInfoStream.message [BD][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: prune sis=org.apache.lucene.index.SegmentInfos@9af4bc minGen=243 packetCount=0
[junit4] 2> 302123 T256 C56 oasu.LoggingInfoStream.message [DW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker finishFullFlush success=true
[junit4] 2> 302124 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: startCommit(): start
[junit4] 2> 302124 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: skip startCommit(): no changes pending
[junit4] 2> 302124 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: pendingCommit == null; skip
[junit4] 2> 302124 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: commit: done
[junit4] 2> 302125 T256 C56 oasu.LoggingInfoStream.message [IW][SUITE-SolrExampleXMLTest-seed#[C599F017F2B3788A]-worker]: at close: _14(4.7):C1 _15(4.7):C1
[junit4] 2> 302125 T256 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 302126 T256 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 302126 T256 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733;done=false>>]
[junit4] 2> 302126 T256 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733
[junit4] 2> 302127 T256 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index;done=false>>]
[junit4] 2> 302127 T256 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-solrj/test/J0/solrtest-SolrExampleXMLTest-1395828400733/index
[junit4] 2> 302127 T256 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 302179 T256 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene46: {}, docValues:{}, sim=DefaultSimilarity, locale=es_PR, timezone=America/Eirunepe
[junit4] 2> NOTE: Linux 3.8.0-37-generic i386/Oracle Corporation 1.7.0_51 (32-bit)/cpus=8,threads=1,free=18116472,total=106954752
[junit4] 2> NOTE: All tests run in this JVM: [LargeVolumeEmbeddedTest, TermsResponseTest, LargeVolumeJettyTest, ClientUtilsTest, TestXMLEscaping, NoOpResponseParserTest, TestJavaBinCodec, AnlysisResponseBaseTest, TestUpdateRequestCodec, CloudSolrServerTest, TestDocumentObjectBinder, ModifiableSolrParamsTest, SolrExampleStreamingBinaryTest, SolrExampleBinaryTest, SolrExampleXMLTest]
[junit4] Completed on J0 in 208.20s, 26 tests, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:459: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:439: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build.xml:202: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/common-build.xml:499: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/lucene/common-build.xml:1278: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/lucene/common-build.xml:911: There were test failures: 48 suites, 281 tests, 1 error, 1 ignored (1 assumption)
Total time: 58 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_51 -client -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.7-Linux (32bit/ibm-j9-jdk7) - Build # 38 -
Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.7-Linux/38/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
3 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
Error Message:
Suite timeout exceeded (>= 7200000 msec).
Stack Trace:
java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
at __randomizedtesting.SeedInfo.seed([C6F54B120A1E6EE9]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
Error Message:
Captured an uncaught exception in thread: Thread[id=3103, name=RecoveryThread, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3103, name=RecoveryThread, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
Caused by: java.lang.AssertionError: file _1.cfs does not exist
at __randomizedtesting.SeedInfo.seed([C6F54B120A1E6EE9]:0)
at org.apache.lucene.index.IndexWriter.filesExist(IndexWriter.java:4390)
at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4456)
at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:2953)
at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3049)
at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3016)
at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:578)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:396)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:247)
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
Test abandoned because suite timeout was reached.
Stack Trace:
java.lang.Exception: Test abandoned because suite timeout was reached.
at __randomizedtesting.SeedInfo.seed([C6F54B120A1E6EE9]:0)
Build Log:
[...truncated 11240 lines...]
[junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4] 2> 785800 T2683 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (true)
[junit4] 2> 785800 T2683 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4] 2> 785803 T2683 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1395845537733
[junit4] 2> 785804 T2683 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 785805 T2684 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 785905 T2683 oasc.ZkTestServer.run start zk server on port:38540
[junit4] 2> 785907 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 786082 T2690 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e183e0 name:ZooKeeperConnection Watcher:127.0.0.1:38540 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 786082 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 786082 T2683 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 786087 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 786088 T2692 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d3fc4361 name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 786088 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 786088 T2683 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 786091 T2683 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 786093 T2683 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 786094 T2683 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 786096 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 786097 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 786100 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 786100 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 786103 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 786103 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 786106 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 786106 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 786109 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 786109 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 786111 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 786112 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 786115 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 786116 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
[junit4] 2> 786122 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 786123 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 786127 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 786128 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 786132 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 786133 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 786137 T2683 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 786139 T2683 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 786211 T2683 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 786214 T2683 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:๕๙๗๘๙
[junit4] 2> 786215 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 786215 T2683 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 786216 T2683 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074
[junit4] 2> 786216 T2683 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/'
[junit4] 2> 786223 T2683 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/solr.xml
[junit4] 2> 786254 T2683 oasc.CoreContainer.<init> New CoreContainer 1378050257
[junit4] 2> 786255 T2683 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/]
[junit4] 2> 786256 T2683 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 786257 T2683 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 786257 T2683 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 786258 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 786258 T2683 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 786259 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 786259 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 786260 T2683 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 786260 T2683 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 786261 T2683 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 786261 T2683 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 786262 T2683 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 786262 T2683 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38540/solr
[junit4] 2> 786263 T2683 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 786264 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 786265 T2703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ea963 name:ZooKeeperConnection Watcher:127.0.0.1:38540 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 786265 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 786267 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 786268 T2705 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f3cf6e4b name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 786268 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 786269 T2683 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 786272 T2683 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 786274 T2683 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 786276 T2683 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59789_
[junit4] 2> 786277 T2683 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59789_
[junit4] 2> 786280 T2683 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 786281 T2683 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 786284 T2683 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:59789_
[junit4] 2> 786285 T2683 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 786287 T2683 oasc.Overseer.start Overseer (id=91478133161132035-127.0.0.1:59789_-n_0000000000) starting
[junit4] 2> 786292 T2683 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 786296 T2707 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 786297 T2683 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 786297 T2707 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 786299 T2683 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 786301 T2683 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 786303 T2706 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 786306 T2708 oasc.ZkController.publish publishing core=collection1 state=down collection=control_collection
[junit4] 2> 786306 T2708 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 786308 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 786308 T2708 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 786309 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 786310 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:59789",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:59789_",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "numShards":"1",
[junit4] 2> "core_node_name":null}
[junit4] 2> 786310 T2706 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
[junit4] 2> 786310 T2706 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 786312 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 786313 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 787309 T2708 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 787309 T2708 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/collection1
[junit4] 2> 787310 T2708 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4] 2> 787311 T2708 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 787311 T2708 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 787312 T2708 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 787312 T2708 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/collection1/'
[junit4] 2> 787313 T2708 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/collection1/lib/classes/' to classloader
[junit4] 2> 787314 T2708 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/collection1/lib/README' to classloader
[junit4] 2> 787365 T2708 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 787398 T2708 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 787400 T2708 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 787405 T2708 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 787696 T2708 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 787699 T2708 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 787701 T2708 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 787705 T2708 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 787721 T2708 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4] 2> 787721 T2708 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1395845538074/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/
[junit4] 2> 787721 T2708 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9afd7b08
[junit4] 2> 787722 T2708 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data
[junit4] 2> 787722 T2708 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/index/
[junit4] 2> 787723 T2708 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/index' doesn't exist. Creating new index...
[junit4] 2> 787723 T2708 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/index
[junit4] 2> 787724 T2708 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=49, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.14311032420306866]
[junit4] 2> 787742 T2708 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/index,segFN=segments_1,generation=1}
[junit4] 2> 787743 T2708 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 787744 T2708 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 787745 T2708 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 787745 T2708 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 787745 T2708 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 787746 T2708 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 787746 T2708 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 787746 T2708 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 787747 T2708 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 787747 T2708 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 787747 T2708 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 787748 T2708 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 787748 T2708 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 787748 T2708 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 787749 T2708 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 787749 T2708 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 787749 T2708 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 787750 T2708 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 787753 T2708 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 787753 T2708 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 787754 T2708 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=4, maxMergeAtOnceExplicit=7, maxMergedSegmentMB=65.61328125, floorSegmentMB=1.5751953125, forceMergeDeletesPctAllowed=14.704427509356368, segmentsPerTier=24.0, maxCFSSegmentSizeMB=0.8818359375, noCFSRatio=0.0
[junit4] 2> 787755 T2708 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/control/data/index,segFN=segments_1,generation=1}
[junit4] 2> 787755 T2708 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 787755 T2708 oass.SolrIndexSearcher.<init> Opening Searcher@dba00e4a[collection1] main
[junit4] 2> 787757 T2709 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dba00e4a[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 787757 T2708 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 787758 T2683 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1
[junit4] 2> 787759 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 787758 T2712 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59789 collection:control_collection shard:shard1
[junit4] 2> 787761 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 787763 T2714 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9c0c2338 name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 787763 T2712 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4] 2> 787763 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 787764 T2683 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 787767 T2683 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 787768 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 787770 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787770 T2712 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 787771 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C1555 name=collection1 org.apache.solr.core.SolrCore@a161e64a url=http://127.0.0.1:59789/collection1 node=127.0.0.1:59789_ C1555_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:59789, core=collection1, node_name=127.0.0.1:59789_}
[junit4] 2> 787771 T2712 C1555 P59789 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59789/collection1/
[junit4] 2> 787771 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 787772 T2712 C1555 P59789 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 787773 T2712 C1555 P59789 oasc.SyncStrategy.syncToMe http://127.0.0.1:59789/collection1/ has no replicas
[junit4] 2> 787773 T2712 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59789/collection1/ shard1
[junit4] 2> 787774 T2712 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4] 2> 787775 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787779 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787782 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787854 T2683 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 1
[junit4] 2> 787855 T2683 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 787857 T2683 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:๓๕๔๑๖
[junit4] 2> 787858 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 787858 T2683 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 787859 T2683 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696
[junit4] 2> 787859 T2683 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/'
[junit4] 2> 787868 T2683 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/solr.xml
[junit4] 2> 787885 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 787885 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 787901 T2683 oasc.CoreContainer.<init> New CoreContainer 313066369
[junit4] 2> 787902 T2683 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/]
[junit4] 2> 787903 T2683 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 787903 T2683 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 787904 T2683 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 787904 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 787905 T2683 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 787905 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 787906 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 787906 T2683 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 787907 T2683 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 787908 T2683 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 787908 T2683 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 787909 T2683 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 787909 T2683 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38540/solr
[junit4] 2> 787910 T2683 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 787911 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 787912 T2725 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1200ba51 name:ZooKeeperConnection Watcher:127.0.0.1:38540 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 787912 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 787914 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 787915 T2727 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f1083e43 name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 787915 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 787918 T2683 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 787930 T2712 oasc.ZkController.register We are http://127.0.0.1:59789/collection1/ and leader is http://127.0.0.1:59789/collection1/
[junit4] 2> 787930 T2712 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59789
[junit4] 2> 787930 T2712 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 787930 T2712 oasc.ZkController.publish publishing core=collection1 state=active collection=control_collection
[junit4] 2> 787931 T2712 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 787932 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787932 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787932 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 787932 T2712 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 787933 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 787934 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:59789",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:59789_",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"control_collection",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":"core_node1"}
[junit4] 2> 787936 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 788038 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 788038 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 788039 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 788921 T2683 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35416_
[junit4] 2> 788922 T2683 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35416_
[junit4] 2> 788924 T2714 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 788925 T2727 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 788925 T2705 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 788930 T2728 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
[junit4] 2> 788930 T2728 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 788935 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 788935 T2728 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 788935 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 788936 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 788936 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 788937 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:35416",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:35416_",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":null}
[junit4] 2> 788937 T2706 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 788938 T2706 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 788941 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 789044 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 789044 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 789044 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 789936 T2728 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 789936 T2728 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/collection1
[junit4] 2> 789936 T2728 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 789937 T2728 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 789937 T2728 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 789938 T2728 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 789938 T2728 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/collection1/'
[junit4] 2> 789939 T2728 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/collection1/lib/classes/' to classloader
[junit4] 2> 789939 T2728 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/collection1/lib/README' to classloader
[junit4] 2> 789979 T2728 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 790020 T2728 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 790021 T2728 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 790026 T2728 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 790330 T2728 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 790334 T2728 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 790337 T2728 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 790342 T2728 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 790362 T2728 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4] 2> 790363 T2728 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1395845539696/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/
[junit4] 2> 790363 T2728 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9afd7b08
[junit4] 2> 790364 T2728 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1
[junit4] 2> 790365 T2728 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/index/
[junit4] 2> 790365 T2728 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/index' doesn't exist. Creating new index...
[junit4] 2> 790366 T2728 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/index
[junit4] 2> 790367 T2728 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=49, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.14311032420306866]
[junit4] 2> 790369 T2728 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/index,segFN=segments_1,generation=1}
[junit4] 2> 790370 T2728 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 790372 T2728 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 790372 T2728 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 790373 T2728 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 790373 T2728 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 790373 T2728 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 790374 T2728 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 790374 T2728 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 790374 T2728 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 790375 T2728 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 790375 T2728 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 790375 T2728 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 790376 T2728 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 790376 T2728 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 790376 T2728 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 790377 T2728 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 790377 T2728 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 790378 T2728 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 790381 T2728 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 790381 T2728 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 790382 T2728 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=4, maxMergeAtOnceExplicit=7, maxMergedSegmentMB=65.61328125, floorSegmentMB=1.5751953125, forceMergeDeletesPctAllowed=14.704427509356368, segmentsPerTier=24.0, maxCFSSegmentSizeMB=0.8818359375, noCFSRatio=0.0
[junit4] 2> 790383 T2728 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty1/index,segFN=segments_1,generation=1}
[junit4] 2> 790383 T2728 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 790383 T2728 oass.SolrIndexSearcher.<init> Opening Searcher@ea69d8d7[collection1] main
[junit4] 2> 790386 T2729 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ea69d8d7[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 790387 T2728 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 790388 T2683 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1
[junit4] 2> 790389 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 790388 T2732 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35416 collection:collection1 shard:shard2
[junit4] 2> 790393 T2732 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 790399 T2732 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 790400 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790400 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790400 T2732 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 790401 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790401 T2732 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C1556 name=collection1 org.apache.solr.core.SolrCore@45b9b7af url=http://127.0.0.1:35416/collection1 node=127.0.0.1:35416_ C1556_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:35416, core=collection1, node_name=127.0.0.1:35416_}
[junit4] 2> 790401 T2732 C1556 P35416 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35416/collection1/
[junit4] 2> 790402 T2732 C1556 P35416 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 790402 T2732 C1556 P35416 oasc.SyncStrategy.syncToMe http://127.0.0.1:35416/collection1/ has no replicas
[junit4] 2> 790402 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 790402 T2732 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35416/collection1/ shard2
[junit4] 2> 790403 T2732 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 790405 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790407 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790411 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790485 T2683 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 2
[junit4] 2> 790485 T2683 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 790488 T2683 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:๕๑๖๒๐
[junit4] 2> 790488 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 790489 T2683 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 790489 T2683 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319
[junit4] 2> 790490 T2683 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/'
[junit4] 2> 790497 T2683 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/solr.xml
[junit4] 2> 790513 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790513 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790513 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790529 T2683 oasc.CoreContainer.<init> New CoreContainer 1196480550
[junit4] 2> 790529 T2683 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/]
[junit4] 2> 790531 T2683 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 790531 T2683 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 790532 T2683 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 790532 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 790532 T2683 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 790533 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 790533 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 790534 T2683 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 790534 T2683 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 790535 T2683 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 790536 T2683 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 790536 T2683 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 790537 T2683 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38540/solr
[junit4] 2> 790537 T2683 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 790538 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 790540 T2743 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b5770bc1 name:ZooKeeperConnection Watcher:127.0.0.1:38540 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 790540 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 790542 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 790543 T2745 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28cf6980 name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 790543 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 790548 T2683 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 790558 T2732 oasc.ZkController.register We are http://127.0.0.1:35416/collection1/ and leader is http://127.0.0.1:35416/collection1/
[junit4] 2> 790558 T2732 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35416
[junit4] 2> 790559 T2732 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 790559 T2732 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
[junit4] 2> 790559 T2732 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 790560 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790560 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790560 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790561 T2732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 790561 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 790562 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:35416",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:35416_",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":"core_node1"}
[junit4] 2> 790564 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 790666 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790666 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790666 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 790666 T2745 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 791550 T2683 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51620_
[junit4] 2> 791552 T2683 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51620_
[junit4] 2> 791554 T2745 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 791554 T2727 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 791554 T2714 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 791554 T2705 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 791559 T2746 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
[junit4] 2> 791559 T2746 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 791560 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 791560 T2746 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 791560 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 791561 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 791562 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 791562 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:51620",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:51620_",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":null}
[junit4] 2> 791562 T2706 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 791563 T2706 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 791564 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 791667 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 791667 T2745 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 791667 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 791667 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 792561 T2746 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 792564 T2746 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/collection1
[junit4] 2> 792565 T2746 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 792565 T2746 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 792566 T2746 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 792567 T2746 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 792567 T2746 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/collection1/'
[junit4] 2> 792568 T2746 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/collection1/lib/classes/' to classloader
[junit4] 2> 792568 T2746 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/collection1/lib/README' to classloader
[junit4] 2> 792604 T2746 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 792643 T2746 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 792644 T2746 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 792650 T2746 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 792948 T2746 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 792951 T2746 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 792953 T2746 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 792957 T2746 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 792977 T2746 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4] 2> 792977 T2746 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1395845542319/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/
[junit4] 2> 792977 T2746 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9afd7b08
[junit4] 2> 792978 T2746 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2
[junit4] 2> 792979 T2746 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/index/
[junit4] 2> 792979 T2746 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/index' doesn't exist. Creating new index...
[junit4] 2> 792979 T2746 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/index
[junit4] 2> 792980 T2746 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=49, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.14311032420306866]
[junit4] 2> 792982 T2746 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/index,segFN=segments_1,generation=1}
[junit4] 2> 792983 T2746 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 792985 T2746 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 792985 T2746 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 792986 T2746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 792986 T2746 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 792986 T2746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 792986 T2746 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 792987 T2746 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 792987 T2746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 792987 T2746 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 792988 T2746 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 792988 T2746 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 792988 T2746 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 792989 T2746 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 792989 T2746 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 792989 T2746 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 792990 T2746 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 792991 T2746 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 792993 T2746 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 792994 T2746 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 792994 T2746 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=4, maxMergeAtOnceExplicit=7, maxMergedSegmentMB=65.61328125, floorSegmentMB=1.5751953125, forceMergeDeletesPctAllowed=14.704427509356368, segmentsPerTier=24.0, maxCFSSegmentSizeMB=0.8818359375, noCFSRatio=0.0
[junit4] 2> 792995 T2746 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty2/index,segFN=segments_1,generation=1}
[junit4] 2> 792995 T2746 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 792996 T2746 oass.SolrIndexSearcher.<init> Opening Searcher@bcaad3d[collection1] main
[junit4] 2> 792998 T2747 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bcaad3d[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 793000 T2746 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 793001 T2683 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1
[junit4] 2> 793002 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 793001 T2750 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51620 collection:collection1 shard:shard1
[junit4] 2> 793007 T2750 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 793020 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 793023 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793023 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793024 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793024 T2750 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 793025 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C1557 name=collection1 org.apache.solr.core.SolrCore@2a44fe51 url=http://127.0.0.1:51620/collection1 node=127.0.0.1:51620_ C1557_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:51620, core=collection1, node_name=127.0.0.1:51620_}
[junit4] 2> 793025 T2750 C1557 P51620 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51620/collection1/
[junit4] 2> 793026 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 793026 T2750 C1557 P51620 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 793027 T2750 C1557 P51620 oasc.SyncStrategy.syncToMe http://127.0.0.1:51620/collection1/ has no replicas
[junit4] 2> 793027 T2750 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51620/collection1/ shard1
[junit4] 2> 793028 T2750 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 793030 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793035 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793040 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793074 T2683 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 3
[junit4] 2> 793075 T2683 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 793077 T2683 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:๓๔๓๘๑
[junit4] 2> 793078 T2683 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 793078 T2683 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 793079 T2683 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932
[junit4] 2> 793079 T2683 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/'
[junit4] 2> 793087 T2683 oasc.ConfigSolr.fromFile Loading container configuration from /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/solr.xml
[junit4] 2> 793119 T2683 oasc.CoreContainer.<init> New CoreContainer -800169611
[junit4] 2> 793119 T2683 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/]
[junit4] 2> 793121 T2683 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 793121 T2683 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 793121 T2683 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 793122 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 793122 T2683 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 793123 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 793123 T2683 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 793124 T2683 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 793124 T2683 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 793125 T2683 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 793126 T2683 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 793126 T2683 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 793127 T2683 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38540/solr
[junit4] 2> 793127 T2683 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 793128 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 793130 T2761 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@396258ea name:ZooKeeperConnection Watcher:127.0.0.1:38540 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 793130 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 793132 T2683 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 793133 T2763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cdbdd253 name:ZooKeeperConnection Watcher:127.0.0.1:38540/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 793134 T2683 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 793137 T2683 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 793143 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793143 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793143 T2763 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793143 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793144 T2745 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793186 T2750 oasc.ZkController.register We are http://127.0.0.1:51620/collection1/ and leader is http://127.0.0.1:51620/collection1/
[junit4] 2> 793187 T2750 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51620
[junit4] 2> 793187 T2750 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 793187 T2750 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
[junit4] 2> 793187 T2750 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 793188 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793189 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793189 T2750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 793189 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793190 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 793190 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:51620",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:51620_",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":"core_node2"}
[junit4] 2> 793250 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 793353 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793353 T2745 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793353 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793353 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 793353 T2763 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4] 2> 794140 T2683 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34381_
[junit4] 2> 794142 T2683 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34381_
[junit4] 2> 794145 T2714 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 794145 T2705 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 794145 T2727 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 794145 T2745 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 794145 T2763 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 794153 T2764 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
[junit4] 2> 794153 T2764 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 794154 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 794154 T2764 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 794155 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 794155 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 794156 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 794157 T2706 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:34381",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:34381_",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "core_node_name":null}
[junit4] 2> 794157 T2706 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 794157 T2706 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 794159 T2705 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 794261 T2714 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 794261 T2727 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 794262 T2745 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 794262 T2705 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 794261 T2763 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 795155 T2764 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 795155 T2764 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/collection1
[junit4] 2> 795156 T2764 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 795156 T2764 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 795157 T2764 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 795157 T2764 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 795158 T2764 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/collection1/'
[junit4] 2> 795158 T2764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/collection1/lib/classes/' to classloader
[junit4] 2> 795159 T2764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/collection1/lib/README' to classloader
[junit4] 2> 795186 T2764 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 795229 T2764 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 795230 T2764 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 795235 T2764 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 795515 T2764 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 795517 T2764 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 795519 T2764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 795523 T2764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 795538 T2764 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4] 2> 795538 T2764 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1395845544932/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3/
[junit4] 2> 795539 T2764 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@9afd7b08
[junit4] 2> 795539 T2764 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3
[junit4] 2> 795540 T2764 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3/index/
[junit4] 2> 795540 T2764 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3/index' doesn't exist. Creating new index...
[junit4] 2> 795540 T2764 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3/index
[junit4] 2> 795541 T2764 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=49, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.14311032420306866]
[junit4] 2> 795544 T2764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1395845537733/jetty3/index,segFN=segments_1,generation=1}
[junit4] 2> 795544 T2764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 795546 T2764 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 795547 T2764 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 795547 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 795547 T2764 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 795547 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 795548 T2764 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 795548 T2764 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 795548 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 795549 T2764 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 795549 T2764 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 795549 T2764 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 795550 T2764 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 795550 T2764 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 795550 T2764 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 795551 T2764 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 795551 T2764 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 795552 T2764 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 795554 T2764 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[...truncated too long message...]
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2054)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:818)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1093)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1155)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:640)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 95) Thread[id=3076, name=qtp-458435789-3076 Selector1, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at org.eclipse.jetty.io.nio.SelectorManager$1.run(SelectorManager.java:290)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 96) Thread[id=2943, name=Thread-1393, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at java.lang.Object.wait(Native Method)
[junit4] 2> at java.lang.Object.wait(Object.java:172)
[junit4] 2> at org.apache.solr.core.CloserThread.run(CoreContainer.java:1018)
[junit4] 2> 97) Thread[id=2930, name=qtp-1514414976-2930 Acceptor0 SelectChannelConnector@127.0.0.1:๕๓๘๑๐, state=BLOCKED, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:956)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 98) Thread[id=2942, name=searcherExecutor-1740-thread-1, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:197)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2054)
[junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:453)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1093)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1155)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:640)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 99) Thread[id=2852, name=qtp371193876-2852 Acceptor1 SelectChannelConnector@127.0.0.1:๕๘๑๖๖, state=BLOCKED, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:956)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 100) Thread[id=2783, name=searcherExecutor-1676-thread-1, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:197)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2054)
[junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:453)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1093)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1155)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:640)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=th_TH_TH_#u-nu-thai, timezone=America/Nome
[junit4] 2> NOTE: Linux 3.8.0-37-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=113,free=80262048,total=253231104
[junit4] 2> NOTE: All tests run in this JVM: [TestFoldingMultitermQuery, TestBinaryResponseWriter, TestSolrXmlPersistor, TestComponentsName, TestSolrQueryParserResource, ShardRoutingCustomTest, TestNRTOpen, SuggestComponentTest, SimplePostToolTest, AlternateDirectoryTest, TestDefaultSimilarityFactory, TestQuerySenderNoQuery, PathHierarchyTokenizerFactoryTest, HdfsLockFactoryTest, FullSolrCloudDistribCmdsTest, AddBlockUpdateTest, TestClassNameShortening, CoreContainerCoreInitFailuresTest, SSLMigrationTest, TestCSVResponseWriter, DebugComponentTest, StatsComponentTest, TestSolrDeletionPolicy2, TestStressRecovery, TestAnalyzedSuggestions, DirectSolrSpellCheckerTest, OpenExchangeRatesOrgProviderTest, SuggesterTSTTest, TestDynamicFieldResource, OpenCloseCoreStressTest, TestSolrXmlPersistence, TestFieldCollectionResource, IndexSchemaRuntimeFieldTest, TestCollapseQParserPlugin, TestAtomicUpdateErrorCases, TestFieldResource, SuggesterWFSTTest, NotRequiredUniqueKeyTest, TestCodecSupport, RequiredFieldsTest, TestRandomFaceting, BadCopyFieldTest, StressHdfsTest, TestFiltering, TestReloadAndDeleteDocs, TestSolr4Spatial, TestDistribDocBasedVersion, DirectUpdateHandlerTest, TestUtils, DistributedDebugComponentTest, TestJmxIntegration, SolrRequestParserTest, DateFieldTest, ChaosMonkeyNothingIsSafeTest, DisMaxRequestHandlerTest, CoreAdminCreateDiscoverTest, RemoteQueryErrorTest, BlockCacheTest, TestImplicitCoreProperties, TestSolrJ, DeleteReplicaTest, ConvertedLegacyTest, TestRangeQuery, MinimalSchemaTest, TestDistributedMissingSort, ShardSplitTest, PingRequestHandlerTest, LeaderElectionIntegrationTest, TestSweetSpotSimilarityFactory, XsltUpdateRequestHandlerTest, TestFieldTypeResource, PrimUtilsTest, CurrencyFieldXmlFileTest, SortByFunctionTest, TestCoreDiscovery, TestAnalyzeInfixSuggestions, TestPhraseSuggestions, TestUpdate, DistributedQueryComponentCustomSortTest, TestSchemaSimilarityResource, TestDistributedSearch, ChaosMonkeySafeLeaderTest]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.seed=C6F54B120A1E6EE9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=th_TH_TH_#u-nu-thai -Dtests.timezone=America/Nome -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.00s J1 | ChaosMonkeySafeLeaderTest (suite) <<<
[junit4] > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4] > at __randomizedtesting.SeedInfo.seed([C6F54B120A1E6EE9]:0)Throwable #2: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3103, name=RecoveryThread, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4] > Caused by: java.lang.AssertionError: file _1.cfs does not exist
[junit4] > at __randomizedtesting.SeedInfo.seed([C6F54B120A1E6EE9]:0)
[junit4] > at org.apache.lucene.index.IndexWriter.filesExist(IndexWriter.java:4390)
[junit4] > at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4456)
[junit4] > at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:2953)
[junit4] > at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3049)
[junit4] > at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3016)
[junit4] > at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:578)
[junit4] > at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:396)
[junit4] > at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:247)
[junit4] Completed on J1 in 7226.28s, 1 test, 3 errors <<< FAILURES!
[...truncated 32 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:459: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:452: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/build.xml:189: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/solr/common-build.xml:499: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/lucene/common-build.xml:1278: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.7-Linux/lucene/common-build.xml:911: There were test failures: 365 suites, 1570 tests, 2 suite-level errors, 1 error, 60 ignored (7 assumptions)
Total time: 163 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure