lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dyer, James" <James.D...@ingramcontent.com>
Subject RE: TestSqlEntityProcessorDelta failures on Policeman Jenkins
Date Wed, 05 Dec 2012 18:14:17 GMT
Robert,

Thank you for taking time on this!!

The test first does a full import with 20 documents.  Then it randomly chooses to add,modify and/or delete documents from the rdbms then does a delta import.  It then checks that the index now has the correct # of documents and that they match the actual changes to the rdbms.  The failures are always on the delta imports.  The failure on this seed is that it is does a query and expects 22 results but it only gets 20 back.

When the full import ends, it writes the last index timestamp in a file called "dataimport.properties".  Unimaginably, this file only records precision to seconds.  The delta updates use this recorded timestamp to know which documents changed since the last import.  To handle this in the test, it pads the "last modified" column values in the rdbms so we shouldn't get strange failures due to timing issues.  My chief worry is that I did this incorrectly and maybe Policeman is a little faster or something and can trip a timing issue.  So yesterday I committed a whole bunch of logging on this test to try and see what is happening.  But strangely it hasn't failed since then whereas it was failing multiple times per day.

One thing I added with the logging is a <propertyWriter /> element (added in SOLR-4051 to allow for localization on "dataimport.properties").  This let me place the file in a convienent location so I could log out its contents during the test.  Without <propertyWriter /> its supposed to use the Root locale and the legacy default file location.   Best I can tell this shouldn't affect the test outcome but maybe it is, or maybe something else I did when I added more logging did.  Or maybe I just need to be patient to see if it can fail again so I can see the logging.  If it doesn't fail for a while, I might go revert the changes one at a time to see if I can figure out which logging-related change "fixed" this test.

I'm not sure how the time of the day would affect this test, but I generally don't like to leave failing tests out there very long, so from the Policeman's timezone, these failures all occur in the afternoon to evening hours, as I tend to do my commits first thing in the morning and I live at GMT-6.  If I don't think I can fix it the same day, I'll just commit an @Ignore and come back the next morning.

If reading all of this babble gives you any ideas, I would like them, as I am running out.

James Dyer
E-Commerce Systems
Ingram Content Group
(615) 213-4311

From: Robert Muir [mailto:rcmuir@gmail.com]
Sent: Wednesday, December 05, 2012 11:18 AM
To: dev@lucene.apache.org
Subject: Re: TestSqlEntityProcessorDelta failures on Policeman Jenkins

I tried to reproduce them, but I dont understand whats failing.

I took the expected and actual xml, and indented it and do a diff, but its the same. I must be missing something as to what the actual failure is.

Separately i tried running with java7, reproducing the whole master seed and configuration (-Dtests.seed=xxxxx -Dtests.jvms=2), but the failure doesn't reproduce either. Is the test somehow sensitive to the current time of day that it is running?
On Tue, Dec 4, 2012 at 11:42 AM, Dyer, James <James.Dyer@ingramcontent.com<mailto:James.Dyer@ingramcontent.com>> wrote:
Can anyone help me reproduce these failures?  I both have a 2-core Windows 32-bit java 6 workstation and a 8-core Linux 64-bit java 7 server and cannot reproduce any of the failures

...neither with:
ant test -Dtestcase=TestSqlEntityProcessorDelta -Dtests.method=testWithComplexTransformer -Dtests.seed=FBAB1A7FB438C056:91A16BF4DFCECEEB"

...or:
ant test -Dtestcase=TestSqlEntityProcessorDelta -Dtests.method=testWithComplexTransformer -Dtests.seed=FBAB1A7FB438C056 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_LB -Dtests.timezone=US/Aleutian -Dtests.file.encoding=UTF-8"

...or by running hundreds of iterations, or by running all the dih tests.  I really want to have a good non-@Ignore test for this but need to figure out what is still wrong.

Any ideaS?

James Dyer
E-Commerce Systems
Ingram Content Group
(615) 213-4311<tel:%28615%29%20213-4311>


-----Original Message-----
From: Policeman Jenkins Server [mailto:jenkins@sd-datasolutions.de<mailto:jenkins@sd-datasolutions.de>]
Sent: Tuesday, December 04, 2012 10:17 AM
To: dev@lucene.apache.org<mailto:dev@lucene.apache.org>; jdyer@apache.org<mailto:jdyer@apache.org>
Subject: [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b65) - Build # 3059 - Failure!

Build: http://jenkins.sd-datasolutions.de/job/Lucene-Solr-trunk-Linux/3059/
Java: 32bit/jdk1.8.0-ea-b65 -server -XX:+UseConcMarkSweepGC

1 tests failed.
FAILED:  org.apache.solr.handler.dataimport.TestSqlEntityProcessorDelta.testWithComplexTransformer

Error Message:
Exception during query

Stack Trace:
java.lang.RuntimeException: Exception during query
        at __randomizedtesting.SeedInfo.seed([FBAB1A7FB438C056:91A16BF4DFCECEEB]:0)
        at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:515)
        at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:482)
        at org.apache.solr.handler.dataimport.AbstractSqlEntityProcessorTestCase.complexTransform(AbstractSqlEntityProcessorTestCase.java:99)
        at org.apache.solr.handler.dataimport.TestSqlEntityProcessorDelta.testWithComplexTransformer(TestSqlEntityProcessorDelta.java:59)
        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:474)
        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:45)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
        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:45)
        at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
        at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
        at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
        at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//*[@numFound='22']
        xml response was: <?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"><int name="status">0</int><int name="QTime">0</int><lst name="params"><str name="rows">20</str><str name="start">0</str><str name="qt">standard</str><str name="q">id:TripleThreat-1-*</str><str name="version">2.2</str></lst></lst><result name="response" numFound="20" start="0"><doc><arr name="NAME_mult_s"><str>Jacob</str><str>bocaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-1</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Ethan</str><str>nahtE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-2</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Michael</str><str>leahciM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-3</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Jayden</str><str>nedyaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NP</str><str>PN</str></arr><str name="id">TripleThreat-1-4</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>William</str><str>mailliW</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NO</str><str>ON</str></arr><str name="id">TripleThreat-1-5</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Alexander</str><str>rednaxelA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-6</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Noah</str><str>haoN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-7</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Daniel</str><str>leinaD</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-8</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Aiden</str><str>nediA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-9</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Anthony</str><str>ynohtnA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-10</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Emma</str><str>ammE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-11</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Grace</str><str>ecarG</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-12</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Hailey</str><str>yeliaH</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-13</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Isabella</str><str>allebasI</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-14</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Lily</str><str>yliL</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-15</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Madison</str><str>nosidaM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NC</str><str>CN</str></arr><str name="id">TripleThreat-1-16</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Mia</str><str>aiM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NA</str><str>AN</str></arr><str name="id">TripleThreat-1-17</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Natalie</str><str>eilataN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-18</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Olivia</str><str>aivilO</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-19</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Samantha</str><str>ahtnamaS</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-20</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc></result>
</response>

        request was:rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2
        at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:508)
        ... 43 more




Build Log:
[...truncated 11965 lines...]
[junit4:junit4] Suite: org.apache.solr.handler.dataimport.TestSqlEntityProcessorDelta
[junit4:junit4]   2> 39 T37 oas.SolrTestCaseJ4.initCore ####initCore
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 40 T37 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test-files/dih/solr/collection1/'
[junit4:junit4]   2> 105 T37 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 202 T37 oasc.SolrConfig.<init> Loaded SolrConfig: dataimport-solrconfig.xml
[junit4:junit4]   2> 203 T37 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 208 T37 oass.IndexSchema.readSchema Schema name=dih_test
[junit4:junit4]   2> 294 T37 oass.IndexSchema.readSchema default search field in schema is desc
[junit4:junit4]   2> 296 T37 oass.IndexSchema.readSchema query parser default operator is OR
[junit4:junit4]   2> 298 T37 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 300 T37 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 300 T37 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test-files/dih/solr
[junit4:junit4]   2> 300 T37 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test-files/dih/solr/'
[junit4:junit4]   2> 316 T37 oasc.CoreContainer.<init> New CoreContainer 6099790
[junit4:junit4]   2> 316 T37 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test-files/dih/solr/collection1/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/
[junit4:junit4]   2> 317 T37 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4:junit4]   2> 317 T37 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for newSearcher: org.apache.solr.core.QuerySenderListener{queries=[{q=solr,start=0,rows=10}, {q=rocks,start=0,rows=10}, {q=static newSearcher warming query from solrconfig.xml}]}
[junit4:junit4]   2> 318 T37 oasc.SolrCore.initListeners [collection1] Added SolrEventListener for firstSearcher: org.apache.solr.core.QuerySenderListener{queries=[]}
[junit4:junit4]   2> 318 T37 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 319 T37 oasc.CachingDirectoryFactory.injectLockFactory WARNING No lockType configured for MockDirWrapper(org.apache.lucene.store.RAMDirectory@9ea4a4 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14b46cc) assuming 'simple'
[junit4:junit4]   2> 319 T37 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349 forceNew:false
[junit4:junit4]   2> 319 T37 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 320 T37 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index/
[junit4:junit4]   2> 320 T37 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 321 T37 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index forceNew:false
[junit4:junit4]   2> 323 T37 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 323 T37 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 324 T37 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 325 T37 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "" (default)
[junit4:junit4]   2> 327 T37 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 328 T37 oasc.RequestHandlers.initHandlersFromConfig created /dataimport: org.apache.solr.handler.dataimport.DataImportHandler
[junit4:junit4]   2> 329 T37 oasc.RequestHandlers.initHandlersFromConfig created /search: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 330 T37 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 334 T37 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 342 T37 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 343 T37 oass.SolrIndexSearcher.<init> Opening Searcher@ac6680 main
[junit4:junit4]   2> 343 T37 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 344 T37 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 344 T37 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 345 T37 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 345 T37 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 345 T37 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 346 T37 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 346 T37 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 346 T37 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 347 T37 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 347 T37 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 347 T37 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 354 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@ac6680 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 354 T37 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 364 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 366 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ac6680 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 370 T37 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4:junit4]   2> 376 T37 oas.SolrTestCaseJ4.setUp ###Starting testWithComplexTransformer
[junit4:junit4]   2> ASYNC  NEW_CORE C4 name=collection1 org.apache.solr.core.SolrCore@7255cc
[junit4:junit4]   2> 381 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 382 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 386 T37 C4 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 387 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 390 T37 C4 UPDATE [collection1] webapp=null path=null params={} {deleteByQuery=*:*} 0 9
[junit4:junit4]   2> 419 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 420 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 421 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 421 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 422 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@19c3cf2 main
[junit4:junit4]   2> 423 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@19c3cf2 main{StandardDirectoryReader(segments_2:2)}
[junit4:junit4]   2> 423 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 423 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 424 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 424 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 425 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 425 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19c3cf2 main{StandardDirectoryReader(segments_2:2)}
[junit4:junit4]   2> 432 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 432 T37 C4 UPDATE [collection1] webapp=null path=null params={} {commit=} 0 13
[junit4:junit4]   2> 787 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 788 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 790 T37 C4 oashd.DataImporter.doFullImport Starting Full Import
[junit4:junit4]   2> 791 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 792 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 793 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 795 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 1
[junit4:junit4]   2> 879 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 880 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 888 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_3,generation=3,filenames=[_0.fdx, _0.si<http://0.si>, _0_Lucene40_0.frq, _0_Lucene40_0.tim, segments_3, _0.fnm, _0.fdt, _0_Lucene40_0.tip]
[junit4:junit4]   2> 888 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0.fdx, _0.si<http://0.si>, _0_Lucene40_0.frq, _0_Lucene40_0.tim, segments_3, _0.fnm, _0.fdt, _0_Lucene40_0.tip]
[junit4:junit4]   2> 889 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 891 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@1266589 main
[junit4:junit4]   2> 892 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 896 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1266589 main{StandardDirectoryReader(segments_3:5 _0(5.0):C60)}
[junit4:junit4]   2> 897 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 897 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 898 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 898 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 898 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1266589 main{StandardDirectoryReader(segments_3:5 _0(5.0):C60)}
[junit4:junit4]   2> 898 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 899 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 900 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 900 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.108
[junit4:junit4]   2> 901 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=full-import&commit=true&indent=true&clean=true&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"derby"+transformer%3D"TripleThreatTransformer"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {deleteByQuery=*:*,add=[1, TripleThreat-1-1, TripleThreat-2-1, 2, TripleThreat-1-2, TripleThreat-2-2, 3, TripleThreat-1-3, TripleThreat-2-3, 4, ... (60 adds)],commit=} 0 119
[junit4:junit4]   2> 912 T37 C4 REQ [collection1] webapp=null path=null params={rows=60&sort=id+asc&q=*:*} hits=60 status=0 QTime=2
[junit4:junit4]   2> 925 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2} hits=20 status=0 QTime=0
[junit4:junit4]   2> 947 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:TripleThreat-2-*&version=2.2} hits=20 status=0 QTime=1
[junit4:junit4]   2> 973 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=%2Bid:TripleThreat-1-3+%2BNAME_mult_s:Michael+%2BNAME_mult_s:leahciM++%2BCOUNTRY_CODES_mult_s:NR+%2BCOUNTRY_CODES_mult_s:RN&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 975 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=AddAColumn_s:Added&version=2.2} hits=20 status=0 QTime=0
[junit4:junit4]   2> 977 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 978 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 1026 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 1027 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 1027 T37 C4 oashd.DataImporter.doDeltaImport Starting Delta Import
[junit4:junit4]   2> 1028 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 1029 T37 C4 oashd.DocBuilder.doDelta Starting delta collection.
[junit4:junit4]   2> 1029 T37 C4 oashd.DocBuilder.collectDelta Running ModifiedRowKey() for Entity: People
[junit4:junit4]   2> 1030 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 1031 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 1
[junit4:junit4]   2> 1122 T37 C4 oashd.DocBuilder.collectDelta Completed ModifiedRowKey for Entity: People rows obtained : 0
[junit4:junit4]   2> 1123 T37 C4 oashd.DocBuilder.collectDelta Completed DeletedRowKey for Entity: People rows obtained : 0
[junit4:junit4]   2> 1123 T37 C4 oashd.DocBuilder.collectDelta Completed parentDeltaQuery for Entity: People
[junit4:junit4]   2> 1124 T37 C4 oashd.DocBuilder.doDelta Delta Import completed successfully
[junit4:junit4]   2> 1125 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.97
[junit4:junit4]   2> 1125 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=delta-import&commit=true&indent=true&clean=false&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"derby"+transformer%3D"TripleThreatTransformer"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {} 0 101
[junit4:junit4]   2> 1131 T37 C4 REQ [collection1] webapp=null path=null params={rows=48&sort=id+asc&q=*:*} hits=60 status=0 QTime=1
[junit4:junit4]   2> 1135 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2} hits=20 status=0 QTime=0
[junit4:junit4]   2> 1140 T37 oas.SolrTestCaseJ4.assertQ SEVERE REQUEST FAILED: xpath=//*[@numFound='22']
[junit4:junit4]   2>            xml response was: <?xml version="1.0" encoding="UTF-8"?>
[junit4:junit4]   2>    <response>
[junit4:junit4]   2>    <lst name="responseHeader"><int name="status">0</int><int name="QTime">0</int><lst name="params"><str name="rows">20</str><str name="start">0</str><str name="qt">standard</str><str name="q">id:TripleThreat-1-*</str><str name="version">2.2</str></lst></lst><result name="response" numFound="20" start="0"><doc><arr name="NAME_mult_s"><str>Jacob</str><str>bocaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-1</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Ethan</str><str>nahtE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-2</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Michael</str><str>leahciM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-3</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Jayden</str><str>nedyaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NP</str><str>PN</str></arr><str name="id">TripleThreat-1-4</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>William</str><str>mailliW</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NO</str><str>ON</str></arr><str name="id">TripleThreat-1-5</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Alexander</str><str>rednaxelA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-6</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Noah</str><str>haoN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-7</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Daniel</str><str>leinaD</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-8</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Aiden</str><str>nediA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-9</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Anthony</str><str>ynohtnA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-10</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Emma</str><str>ammE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-11</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Grace</str><str>ecarG</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-12</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Hailey</str><str>yeliaH</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-13</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Isabella</str><str>allebasI</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-14</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Lily</str><str>yliL</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-15</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Madison</str><str>nosidaM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NC</str><str>CN</str></arr><str name="id">TripleThreat-1-16</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Mia</str><str>aiM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NA</str><str>AN</str></arr><str name="id">TripleThreat-1-17</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Natalie</str><str>eilataN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-18</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Olivia</str><str>aivilO</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-19</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Samantha</str><str>ahtnamaS</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-20</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc></result>
[junit4:junit4]   2>    </response>
[junit4:junit4]   2>
[junit4:junit4]   2>            request was:rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2
[junit4:junit4]   2> 1142 T37 oasc.SolrException.log SEVERE REQUEST FAILED: rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2:java.lang.RuntimeException: REQUEST FAILED: xpath=//*[@numFound='22']
[junit4:junit4]   2>            xml response was: <?xml version="1.0" encoding="UTF-8"?>
[junit4:junit4]   2>    <response>
[junit4:junit4]   2>    <lst name="responseHeader"><int name="status">0</int><int name="QTime">0</int><lst name="params"><str name="rows">20</str><str name="start">0</str><str name="qt">standard</str><str name="q">id:TripleThreat-1-*</str><str name="version">2.2</str></lst></lst><result name="response" numFound="20" start="0"><doc><arr name="NAME_mult_s"><str>Jacob</str><str>bocaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-1</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Ethan</str><str>nahtE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-2</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Michael</str><str>leahciM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-3</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Jayden</str><str>nedyaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NP</str><str>PN</str></arr><str name="id">TripleThreat-1-4</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>William</str><str>mailliW</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NO</str><str>ON</str></arr><str name="id">TripleThreat-1-5</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Alexander</str><str>rednaxelA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-6</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Noah</str><str>haoN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-7</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Daniel</str><str>leinaD</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-8</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Aiden</str><str>nediA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-9</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Anthony</str><str>ynohtnA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-10</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Emma</str><str>ammE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-11</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Grace</str><str>ecarG</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-12</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Hailey</str><str>yeliaH</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-13</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Isabella</str><str>allebasI</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-14</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Lily</str><str>yliL</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-15</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Madison</str><str>nosidaM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NC</str><str>CN</str></arr><str name="id">TripleThreat-1-16</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Mia</str><str>aiM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NA</str><str>AN</str></arr><str name="id">TripleThreat-1-17</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Natalie</str><str>eilataN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-18</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Olivia</str><str>aivilO</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-19</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Samantha</str><str>ahtnamaS</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-20</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc></result>
[junit4:junit4]   2>    </response>
[junit4:junit4]   2>
[junit4:junit4]   2>            request was:rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2
[junit4:junit4]   2>            at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:508)
[junit4:junit4]   2>            at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:482)
[junit4:junit4]   2>            at org.apache.solr.handler.dataimport.AbstractSqlEntityProcessorTestCase.complexTransform(AbstractSqlEntityProcessorTestCase.java:99)
[junit4:junit4]   2>            at org.apache.solr.handler.dataimport.TestSqlEntityProcessorDelta.testWithComplexTransformer(TestSqlEntityProcessorDelta.java:59)
[junit4:junit4]   2>            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]   2>            at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]   2>            at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]   2>            at java.lang.reflect.Method.invoke(Method.java:474)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]   2>            at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]   2>            at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]   2>            at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]   2>            at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]   2>            at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2>
[junit4:junit4]   2> 1670 T37 oashd.AbstractDataImportHandlerTestCase.tearDown Looking for dataimport.properties at: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/solr/collection1/conf/dataimport.properties
[junit4:junit4]   2> 1671 T37 oas.SolrTestCaseJ4.tearDown ###Ending testWithComplexTransformer
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestSqlEntityProcessorDelta -Dtests.method=testWithComplexTransformer -Dtests.seed=FBAB1A7FB438C056 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_LB -Dtests.timezone=US/Aleutian -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR   1.39s J1 | TestSqlEntityProcessorDelta.testWithComplexTransformer <<<
[junit4:junit4]    > Throwable #1: java.lang.RuntimeException: Exception during query
[junit4:junit4]    >    at __randomizedtesting.SeedInfo.seed([FBAB1A7FB438C056:91A16BF4DFCECEEB]:0)
[junit4:junit4]    >    at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:515)
[junit4:junit4]    >    at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:482)
[junit4:junit4]    >    at org.apache.solr.handler.dataimport.AbstractSqlEntityProcessorTestCase.complexTransform(AbstractSqlEntityProcessorTestCase.java:99)
[junit4:junit4]    >    at org.apache.solr.handler.dataimport.TestSqlEntityProcessorDelta.testWithComplexTransformer(TestSqlEntityProcessorDelta.java:59)
[junit4:junit4]    >    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]    >    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]    >    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    >    at java.lang.reflect.Method.invoke(Method.java:474)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]    >    at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    >    at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    >    at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    >    at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    >    at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]    > Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//*[@numFound='22']
[junit4:junit4]    >    xml response was: <?xml version="1.0" encoding="UTF-8"?>
[junit4:junit4]    > <response>
[junit4:junit4]    > <lst name="responseHeader"><int name="status">0</int><int name="QTime">0</int><lst name="params"><str name="rows">20</str><str name="start">0</str><str name="qt">standard</str><str name="q">id:TripleThreat-1-*</str><str name="version">2.2</str></lst></lst><result name="response" numFound="20" start="0"><doc><arr name="NAME_mult_s"><str>Jacob</str><str>bocaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-1</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Ethan</str><str>nahtE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-2</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Michael</str><str>leahciM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-3</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Jayden</str><str>nedyaJ</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NP</str><str>PN</str></arr><str name="id">TripleThreat-1-4</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>William</str><str>mailliW</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NO</str><str>ON</str></arr><str name="id">TripleThreat-1-5</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Alexander</str><str>rednaxelA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-6</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Noah</str><str>haoN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-7</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Daniel</str><str>leinaD</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-8</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Aiden</str><str>nediA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-9</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Anthony</str><str>ynohtnA</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-10</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Emma</str><str>ammE</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NL</str><str>LN</str></arr><str name="id">TripleThreat-1-11</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Grace</str><str>ecarG</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NI</str><str>IN</str></arr><str name="id">TripleThreat-1-12</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Hailey</str><str>yeliaH</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NG</str><str>GN</str></arr><str name="id">TripleThreat-1-13</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Isabella</str><str>allebasI</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NF</str><str>FN</str></arr><str name="id">TripleThreat-1-14</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Lily</str><str>yliL</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NE</str><str>EN</str></arr><str name="id">TripleThreat-1-15</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Madison</str><str>nosidaM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NC</str><str>CN</str></arr><str name="id">TripleThreat-1-16</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Mia</str><str>aiM</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NA</str><str>AN</str></arr><str name="id">TripleThreat-1-17</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Natalie</str><str>eilataN</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NZ</str><str>ZN</str></arr><str name="id">TripleThreat-1-18</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Olivia</str><str>aivilO</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NU</str><str>UN</str></arr><str name="id">TripleThreat-1-19</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc><doc><arr name="NAME_mult_s"><str>Samantha</str><str>ahtnamaS</str></arr><arr name="COUNTRY_CODES_mult_s"><str>NR</str><str>RN</str></arr><str name="id">TripleThreat-1-20</str><date name="timestamp">2012-12-04T16:16:55.091Z</date></doc></result>
[junit4:junit4]    > </response>
[junit4:junit4]    >
[junit4:junit4]    >    request was:rows=20&start=0&qt=standard&q=id:TripleThreat-1-*&version=2.2
[junit4:junit4]    >    at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:508)
[junit4:junit4]    >    ... 43 more
[junit4:junit4]   2> 1771 T37 oas.SolrTestCaseJ4.setUp ###Starting testWithSimpleTransformer
[junit4:junit4]   2> 1776 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 1777 T37 C4 UPDATE [collection1] webapp=null path=null params={} {deleteByQuery=*:*} 0 2
[junit4:junit4]   2> 1783 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 1784 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_3,generation=3,filenames=[_0.fdx, _0.si<http://0.si>, _0_Lucene40_0.frq, _0_Lucene40_0.tim, segments_3, _0.fnm, _0.fdt, _0_Lucene40_0.tip]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 1784 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 1785 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 1786 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@1ffa3a1 main
[junit4:junit4]   2> 1804 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@1ffa3a1 main{StandardDirectoryReader(segments_4:6)}
[junit4:junit4]   2> 1804 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1805 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 1806 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 1806 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 1806 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 1807 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ffa3a1 main{StandardDirectoryReader(segments_4:6)}
[junit4:junit4]   2> 1807 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 1807 T37 C4 UPDATE [collection1] webapp=null path=null params={} {commit=} 0 24
[junit4:junit4]   2> 1871 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 1872 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 1880 T37 C4 oashd.DataImporter.doFullImport Starting Full Import
[junit4:junit4]   2> 1881 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 1892 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 1893 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:hsqldb:mem:.
[junit4:junit4]   2> 1894 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 1927 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 1928 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 1931 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_5,generation=5,filenames=[_1_Lucene40_0.tim, segments_5, _1.fdt, _1_Lucene40_0.tip, _1_Lucene40_0.frq, _1.si<http://1.si>, _1.fdx, _1.fnm]
[junit4:junit4]   2> 1931 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[_1_Lucene40_0.tim, segments_5, _1.fdt, _1_Lucene40_0.tip, _1_Lucene40_0.frq, _1.si<http://1.si>, _1.fdx, _1.fnm]
[junit4:junit4]   2> 1941 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 1942 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@5172d6 main
[junit4:junit4]   2> 1943 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 1944 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@5172d6 main{StandardDirectoryReader(segments_5:9 _1(5.0):C20)}
[junit4:junit4]   2> 1945 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 1945 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 1946 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 1946 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 1946 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5172d6 main{StandardDirectoryReader(segments_5:9 _1(5.0):C20)}
[junit4:junit4]   2> 1947 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 1951 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 1952 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 1952 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.71
[junit4:junit4]   2> 1953 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=full-import&commit=true&indent=true&clean=true&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"hsqldb"+transformer%3D"AddAColumnTransformer"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {deleteByQuery=*:*,add=[1, 2, 3, 4, 5, 6, 7, 8, 9, 10, ... (20 adds)],commit=} 0 86
[junit4:junit4]   2> 1960 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=AddAColumn_s:Added&version=2.2} hits=20 status=0 QTime=5
[junit4:junit4]   2> 1965 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 1966 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 1991 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 1992 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 1992 T37 C4 oashd.DataImporter.doDeltaImport Starting Delta Import
[junit4:junit4]   2> 1993 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 1994 T37 C4 oashd.DocBuilder.doDelta Starting delta collection.
[junit4:junit4]   2> 1994 T37 C4 oashd.DocBuilder.collectDelta Running ModifiedRowKey() for Entity: People
[junit4:junit4]   2> 1995 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:hsqldb:mem:.
[junit4:junit4]   2> 1995 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 2018 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 2020 T37 C4 oashd.DocBuilder.collectDelta Completed ModifiedRowKey for Entity: People rows obtained : 5
[junit4:junit4]   2> 2020 T37 C4 oashd.DocBuilder.collectDelta Completed DeletedRowKey for Entity: People rows obtained : 3
[junit4:junit4]   2> 2028 T37 C4 oashd.DocBuilder.collectDelta Completed parentDeltaQuery for Entity: People
[junit4:junit4]   2> 2029 T37 C4 oashd.DocBuilder.deleteAll Deleting stale documents
[junit4:junit4]   2> 2030 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 2030 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 15
[junit4:junit4]   2> 2031 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 2031 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 9
[junit4:junit4]   2> 2044 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 2045 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 3
[junit4:junit4]   2> 2049 T37 C4 oashd.DocBuilder.doDelta Delta Import completed successfully
[junit4:junit4]   2> 2050 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 2050 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 2062 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_5,generation=5,filenames=[_1_Lucene40_0.tim, segments_5, _1.fdt, _1_Lucene40_0.tip, _1_Lucene40_0.frq, _1.si<http://1.si>, _1.fdx, _1.fnm]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_6,generation=6,filenames=[_1_Lucene40_0.tim, _1_Lucene40_0.tip, _1.fdt, _2.si<http://2.si>, _1.si<http://1.si>, _1_1.del, _2.fnm, _2.fdx, _2_Lucene40_0.tim, _1_Lucene40_0.frq, _2_Lucene40_0.frq, segments_6, _2_Lucene40_0.tip, _2.fdt, _1.fdx, _1.fnm]
[junit4:junit4]   2> 2063 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_1_Lucene40_0.tim, _1_Lucene40_0.tip, _1.fdt, _2.si<http://2.si>, _1.si<http://1.si>, _1_1.del, _2.fnm, _2.fdx, _2_Lucene40_0.tim, _1_Lucene40_0.frq, _2_Lucene40_0.frq, segments_6, _2_Lucene40_0.tip, _2.fdt, _1.fdx, _1.fnm]
[junit4:junit4]   2> 2064 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 2070 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@208c2a main
[junit4:junit4]   2> 2071 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 2074 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@208c2a main{StandardDirectoryReader(segments_6:12 _1(5.0):C20/7 _2(5.0):C5)}
[junit4:junit4]   2> 2075 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 2075 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2076 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 2076 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 2076 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@208c2a main{StandardDirectoryReader(segments_6:12 _1(5.0):C20/7 _2(5.0):C5)}
[junit4:junit4]   2> 2076 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 2077 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 2078 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 2078 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.85
[junit4:junit4]   2> 2079 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=delta-import&commit=true&indent=true&clean=false&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"hsqldb"+transformer%3D"AddAColumnTransformer"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {delete=[15, 9, 3],add=[7, 1019, 20, 5, 14],commit=} 0 109
[junit4:junit4]   2> 2092 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=AddAColumn_s:Added&version=2.2} hits=18 status=0 QTime=4
[junit4:junit4]   2> 2099 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 2100 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 2101 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:1019&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 2112 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:15&version=2.2} hits=0 status=0 QTime=9
[junit4:junit4]   2> 2123 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:9&version=2.2} hits=0 status=0 QTime=1
[junit4:junit4]   2> 2126 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:3&version=2.2} hits=0 status=0 QTime=1
[junit4:junit4]   2> 2133 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:14&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 2153 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:7&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 2162 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:5&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 2174 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:20&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 2200 T37 oashd.AbstractDataImportHandlerTestCase.tearDown Looking for dataimport.properties at: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/solr/collection1/conf/dataimport.properties
[junit4:junit4]   2> 2200 T37 oas.SolrTestCaseJ4.tearDown ###Ending testWithSimpleTransformer
[junit4:junit4]   2> 2220 T37 oas.SolrTestCaseJ4.setUp ###Starting testChildEntities
[junit4:junit4]   2> 2230 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 2231 T37 C4 UPDATE [collection1] webapp=null path=null params={} {deleteByQuery=*:*} 0 2
[junit4:junit4]   2> 2238 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 2239 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_6,generation=6,filenames=[_1_Lucene40_0.tim, _1_Lucene40_0.tip, _1.fdt, _2.si<http://2.si>, _1.si<http://1.si>, _1_1.del, _2.fnm, _2.fdx, _2_Lucene40_0.tim, _1_Lucene40_0.frq, _2_Lucene40_0.frq, segments_6, _2_Lucene40_0.tip, _2.fdt, _1.fdx, _1.fnm]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_7,generation=7,filenames=[segments_7]
[junit4:junit4]   2> 2239 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 7[segments_7]
[junit4:junit4]   2> 2240 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 2241 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@14419bd main
[junit4:junit4]   2> 2242 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@14419bd main{StandardDirectoryReader(segments_7:13)}
[junit4:junit4]   2> 2243 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2244 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 2244 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2244 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 2245 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14419bd main{StandardDirectoryReader(segments_7:13)}
[junit4:junit4]   2> 2245 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 2245 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 2246 T37 C4 UPDATE [collection1] webapp=null path=null params={} {commit=} 0 9
[junit4:junit4]   2> 2589 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 2589 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 2590 T37 C4 oashd.DataImporter.doFullImport Starting Full Import
[junit4:junit4]   2> 2590 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 2591 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 2597 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 2598 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 2604 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity Countries with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 2605 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 1
[junit4:junit4]   2> 2805 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 2806 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 2808 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_7,generation=7,filenames=[segments_7]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_8,generation=8,filenames=[_3_Lucene40_0.tip, _3.si<http://3.si>, _3_Lucene40_0.frq, _3_Lucene40_0.tim, segments_8, _3.fdt, _3.fdx, _3.fnm]
[junit4:junit4]   2> 2809 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 8[_3_Lucene40_0.tip, _3.si<http://3.si>, _3_Lucene40_0.frq, _3_Lucene40_0.tim, segments_8, _3.fdt, _3.fdx, _3.fnm]
[junit4:junit4]   2> 2810 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 2810 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@c6f2dc main
[junit4:junit4]   2> 2811 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 2813 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@c6f2dc main{StandardDirectoryReader(segments_8:16 _3(5.0):C20)}
[junit4:junit4]   2> 2813 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2813 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2814 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 2814 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 2814 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c6f2dc main{StandardDirectoryReader(segments_8:16 _3(5.0):C20)}
[junit4:junit4]   2> 2814 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 2815 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 2815 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 2816 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.225
[junit4:junit4]   2> 2816 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=full-import&commit=true&indent=true&clean=true&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"derby"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a<entity+name%3D"Countries"+pk%3D"Countries.CODE"+dataSource%3D"derby"+processor%3D"SqlEntityProcessor"+query%3D"SELECT+CODE,+COUNTRY_NAME+FROM+COUNTRIES+WHERE+DELETED+!%3D+'Y'+AND+CODE%3D'${People.COUNTRY_CODE}'+"+deltaQuery%3D"SELECT+CODE+FROM+COUNTRIES+WHERE+DELETED+!%3D+'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"++parentDeltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+AND+COUNTRY_CODE%3D'${Countries.CODE}'+"+>+%0a<field+column%3D"CODE"+name%3D"COUNTRY_CODE_s"+/>+%0a<field+column%3D"COUNTRY_NAME"+name%3D"COUNTRY_NAME_s"+/>+%0a</entity>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {deleteByQuery=*:*,add=[1, 2, 3, 4, 5, 6, 7, 8, 9, 10, ... (20 adds)],commit=} 0 230
[junit4:junit4]   2> 2820 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=*:*&version=2.2} hits=20 status=0 QTime=2
[junit4:junit4]   2> 2865 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=NAME_mult_s:Jayden&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 2895 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=COUNTRY_CODES_mult_s:NR&version=2.2} hits=2 status=0 QTime=0
[junit4:junit4]   2> 2899 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 2900 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 2950 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 2951 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 2951 T37 C4 oashd.DataImporter.doDeltaImport Starting Delta Import
[junit4:junit4]   2> 2952 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 2953 T37 C4 oashd.DocBuilder.doDelta Starting delta collection.
[junit4:junit4]   2> 2953 T37 C4 oashd.DocBuilder.collectDelta Running ModifiedRowKey() for Entity: Countries
[junit4:junit4]   2> 2954 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity Countries with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 2955 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 2961 T37 C4 oashd.DocBuilder.collectDelta Completed ModifiedRowKey for Entity: Countries rows obtained : 0
[junit4:junit4]   2> 2962 T37 C4 oashd.DocBuilder.collectDelta Completed DeletedRowKey for Entity: Countries rows obtained : 0
[junit4:junit4]   2> 2979 T37 C4 oashd.DocBuilder.collectDelta Completed parentDeltaQuery for Entity: Countries
[junit4:junit4]   2> 2979 T37 C4 oashd.DocBuilder.collectDelta Running ModifiedRowKey() for Entity: People
[junit4:junit4]   2> 2980 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:derby:memory:derbyDB;
[junit4:junit4]   2> 2981 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 1
[junit4:junit4]   2> 3030 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 3044 T37 C4 oashd.DocBuilder.collectDelta Completed ModifiedRowKey for Entity: People rows obtained : 2
[junit4:junit4]   2> 3045 T37 C4 oashd.DocBuilder.collectDelta Completed DeletedRowKey for Entity: People rows obtained : 2
[junit4:junit4]   2> 3045 T37 C4 oashd.DocBuilder.collectDelta Completed parentDeltaQuery for Entity: People
[junit4:junit4]   2> 3046 T37 C4 oashd.DocBuilder.deleteAll Deleting stale documents
[junit4:junit4]   2> 3046 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 3047 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 16
[junit4:junit4]   2> 3047 T37 C4 oashd.DocBuilder.findMatchingPkColumn Resolving deltaQuery column 'ID' to match entity's declared pk 'People.ID'
[junit4:junit4]   2> 3048 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 8
[junit4:junit4]   2> 3071 T37 C4 oashd.DocBuilder.doDelta Delta Import completed successfully
[junit4:junit4]   2> 3071 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 3072 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 3075 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_8,generation=8,filenames=[_3_Lucene40_0.tip, _3.si<http://3.si>, _3_Lucene40_0.frq, _3_Lucene40_0.tim, segments_8, _3.fdt, _3.fdx, _3.fnm]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_9,generation=9,filenames=[segments_9, _3_1.del, _3.si<http://3.si>, _3_Lucene40_0.tim, _4_Lucene40_0.tim, _4_Lucene40_0.frq, _4.si<http://4.si>, _4.fdx, _3.fdt, _3.fnm, _4.fdt, _3_Lucene40_0.tip, _3_Lucene40_0.frq, _4_Lucene40_0.tip, _4.fnm, _3.fdx]
[junit4:junit4]   2> 3075 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 9[segments_9, _3_1.del, _3.si<http://3.si>, _3_Lucene40_0.tim, _4_Lucene40_0.tim, _4_Lucene40_0.frq, _4.si<http://4.si>, _4.fdx, _3.fdt, _3.fnm, _4.fdt, _3_Lucene40_0.tip, _3_Lucene40_0.frq, _4_Lucene40_0.tip, _4.fnm, _3.fdx]
[junit4:junit4]   2> 3076 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 3079 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@2cc310 main
[junit4:junit4]   2> 3083 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@2cc310 main{StandardDirectoryReader(segments_9:19 _3(5.0):C20/3 _4(5.0):C2)}
[junit4:junit4]   2> 3084 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3084 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3085 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3085 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 3085 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 3086 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2cc310 main{StandardDirectoryReader(segments_9:19 _3(5.0):C20/3 _4(5.0):C2)}
[junit4:junit4]   2> 3086 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 3087 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 3087 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 3088 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.136
[junit4:junit4]   2> 3088 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=delta-import&commit=true&indent=true&clean=false&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"derby"+transformer%3D"AddAColumnTransformer"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a<entity+name%3D"Countries"+pk%3D"Countries.CODE"+dataSource%3D"derby"+processor%3D"SqlEntityProcessor"+query%3D"SELECT+CODE,+COUNTRY_NAME+FROM+COUNTRIES+WHERE+DELETED+!%3D+'Y'+AND+CODE%3D'${People.COUNTRY_CODE}'+"+deltaQuery%3D"SELECT+CODE+FROM+COUNTRIES+WHERE+DELETED+!%3D+'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"++parentDeltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+AND+COUNTRY_CODE%3D'${Countries.CODE}'+"+>+%0a<field+column%3D"CODE"+name%3D"COUNTRY_CODE_s"+/>+%0a<field+column%3D"COUNTRY_NAME"+name%3D"COUNTRY_NAME_s"+/>+%0a</entity>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {delete=[16, 8],add=[1013, 13],commit=} 0 144
[junit4:junit4]   2> 3096 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=*:*&version=2.2} hits=19 status=0 QTime=5
[junit4:junit4]   2> 3106 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=NAME_mult_s:Jayden&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 3112 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=COUNTRY_CODES_mult_s:NR&version=2.2} hits=2 status=0 QTime=0
[junit4:junit4]   2> 3144 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:1013&version=2.2} hits=1 status=0 QTime=24
[junit4:junit4]   2> 3148 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:8&version=2.2} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3150 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:16&version=2.2} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3161 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:13&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 3681 T37 oashd.AbstractDataImportHandlerTestCase.tearDown Looking for dataimport.properties at: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/solr/collection1/conf/dataimport.properties
[junit4:junit4]   2> 3682 T37 oas.SolrTestCaseJ4.tearDown ###Ending testChildEntities
[junit4:junit4]   2> 3701 T37 oas.SolrTestCaseJ4.setUp ###Starting testSingleEntity
[junit4:junit4]   2> 3705 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 3706 T37 C4 UPDATE [collection1] webapp=null path=null params={} {deleteByQuery=*:*} 0 1
[junit4:junit4]   2> 3731 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 3732 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_9,generation=9,filenames=[segments_9, _3_1.del, _3.si<http://3.si>, _3_Lucene40_0.tim, _4_Lucene40_0.tim, _4_Lucene40_0.frq, _4.si<http://4.si>, _4.fdx, _3.fdt, _3.fnm, _4.fdt, _3_Lucene40_0.tip, _3_Lucene40_0.frq, _4_Lucene40_0.tip, _4.fnm, _3.fdx]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_a,generation=10,filenames=[segments_a]
[junit4:junit4]   2> 3732 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 10[segments_a]
[junit4:junit4]   2> 3733 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 3734 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@17d5486 main
[junit4:junit4]   2> 3735 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@17d5486 main{StandardDirectoryReader(segments_a:20)}
[junit4:junit4]   2> 3736 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3736 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3737 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3737 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 3737 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17d5486 main{StandardDirectoryReader(segments_a:20)}
[junit4:junit4]   2> 3737 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 3737 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 3738 T37 C4 UPDATE [collection1] webapp=null path=null params={} {commit=} 0 7
[junit4:junit4]   2> 3746 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 3746 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 3747 T37 C4 oashd.DataImporter.doFullImport Starting Full Import
[junit4:junit4]   2> 3747 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 3748 T37 C4 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4:junit4]   2> 3749 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:hsqldb:mem:.
[junit4:junit4]   2> 3749 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 3756 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 3757 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 3759 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_a,generation=10,filenames=[segments_a]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_b,generation=11,filenames=[_5.fdt, _5.fnm, _5.si<http://5.si>, segments_b, _5.fdx, _5_Lucene40_0.frq, _5_Lucene40_0.tim, _5_Lucene40_0.tip]
[junit4:junit4]   2> 3760 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 11[_5.fdt, _5.fnm, _5.si<http://5.si>, segments_b, _5.fdx, _5_Lucene40_0.frq, _5_Lucene40_0.tim, _5_Lucene40_0.tip]
[junit4:junit4]   2> 3761 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 3762 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@85c128 main
[junit4:junit4]   2> 3763 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 3768 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@85c128 main{StandardDirectoryReader(segments_b:23 _5(5.0):C20)}
[junit4:junit4]   2> 3768 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3769 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3769 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3770 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 3770 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@85c128 main{StandardDirectoryReader(segments_b:23 _5(5.0):C20)}
[junit4:junit4]   2> 3770 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 3771 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 3777 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 3777 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.29
[junit4:junit4]   2> 3778 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=full-import&commit=true&indent=true&clean=true&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"People.ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"hsqldb"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {deleteByQuery=*:*,add=[1, 2, 3, 4, 5, 6, 7, 8, 9, 10, ... (20 adds)],commit=} 0 34
[junit4:junit4]   2> 3780 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=*:*&version=2.2} hits=20 status=0 QTime=1
[junit4:junit4]   2> 3783 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 3784 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 3788 T37 C4 oashdc.ConfigParseUtil.verifyWithSchema id is a required field in SolrSchema . But not found in DataConfig
[junit4:junit4]   2> 3788 T37 C4 oashd.DataImporter.loadDataConfig Data Configuration loaded successfully
[junit4:junit4]   2> 3789 T37 C4 oashd.DataImporter.doDeltaImport Starting Delta Import
[junit4:junit4]   2> 3789 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 3790 T37 C4 oashd.DocBuilder.doDelta Starting delta collection.
[junit4:junit4]   2> 3791 T37 C4 oashd.DocBuilder.collectDelta Running ModifiedRowKey() for Entity: People
[junit4:junit4]   2> 3792 T37 C4 oashd.JdbcDataSource$1.call Creating a connection for entity People with URL: jdbc:hsqldb:mem:.
[junit4:junit4]   2> 3792 T37 C4 oashd.JdbcDataSource$1.call Time taken for getConnection(): 0
[junit4:junit4]   2> 3795 T37 C4 oashd.DocBuilder.collectDelta Completed ModifiedRowKey for Entity: People rows obtained : 4
[junit4:junit4]   2> 3795 T37 C4 oashd.DocBuilder.collectDelta Completed DeletedRowKey for Entity: People rows obtained : 6
[junit4:junit4]   2> 3806 T37 C4 oashd.DocBuilder.collectDelta Completed parentDeltaQuery for Entity: People
[junit4:junit4]   2> 3806 T37 C4 oashd.DocBuilder.deleteAll Deleting stale documents
[junit4:junit4]   2> 3807 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 12
[junit4:junit4]   2> 3807 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 10
[junit4:junit4]   2> 3808 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 5
[junit4:junit4]   2> 3809 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 20
[junit4:junit4]   2> 3809 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 4
[junit4:junit4]   2> 3809 T37 C4 oashd.SolrWriter.deleteDoc Deleting document: 16
[junit4:junit4]   2> 3815 T37 C4 oashd.DocBuilder.doDelta Delta Import completed successfully
[junit4:junit4]   2> 3816 T37 C4 oashd.DocBuilder.finish Import completed successfully
[junit4:junit4]   2> 3816 T37 C4 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 3819 T37 C4 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_b,generation=11,filenames=[_5.fdt, _5.fnm, _5.si<http://5.si>, segments_b, _5.fdx, _5_Lucene40_0.frq, _5_Lucene40_0.tim, _5_Lucene40_0.tip]
[junit4:junit4]   2>            commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@12f88ec lockFactory=org.apache.lucene.store.NativeFSLockFactory@1853ae8),segFN=segments_c,generation=12,filenames=[_6_Lucene40_0.frq, _6.fnm, _6.fdx, _5_Lucene40_0.tim, _6_Lucene40_0.tip, segments_c, _5.fdt, _6.fdt, _5.fnm, _5.si<http://5.si>, _6_Lucene40_0.tim, _5_1.del, _5.fdx, _5_Lucene40_0.frq, _6.si<http://6.si>, _5_Lucene40_0.tip]
[junit4:junit4]   2> 3820 T37 C4 oasc.SolrDeletionPolicy.updateCommits newest commit = 12[_6_Lucene40_0.frq, _6.fnm, _6.fdx, _5_Lucene40_0.tim, _6_Lucene40_0.tip, segments_c, _5.fdt, _6.fdt, _5.fnm, _5.si<http://5.si>, _6_Lucene40_0.tim, _5_1.del, _5.fdx, _5_Lucene40_0.frq, _6.si<http://6.si>, _5_Lucene40_0.tip]
[junit4:junit4]   2> 3820 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349
[junit4:junit4]   2> 3821 T37 C4 oass.SolrIndexSearcher.<init> Opening Searcher@aa1540 main
[junit4:junit4]   2> 3832 T37 C4 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 3836 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener sending requests to Searcher@aa1540 main{StandardDirectoryReader(segments_c:26 _5(5.0):C20/9 _6(5.0):C4)}
[junit4:junit4]   2> 3837 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=solr&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3837 T39 C4 REQ [collection1] webapp=null path=null params={rows=10&start=0&distrib=false&q=rocks&event=newSearcher} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3838 T39 C4 REQ [collection1] webapp=null path=null params={distrib=false&q=static+newSearcher+warming+query+from+solrconfig.xml&event=newSearcher} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3838 T39 oasc.QuerySenderListener.newSearcher QuerySenderListener done.
[junit4:junit4]   2> 3838 T39 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@aa1540 main{StandardDirectoryReader(segments_c:26 _5(5.0):C20/9 _6(5.0):C4)}
[junit4:junit4]   2> 3838 T39 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 3839 T37 C4 oashd.SimplePropertiesWriter.readIndexerProperties Read dataimport.properties
[junit4:junit4]   2> 3840 T37 C4 oashd.SimplePropertiesWriter.persist Wrote last indexed time to dataimport.properties
[junit4:junit4]   2> 3840 T37 C4 oashd.DocBuilder.execute Time taken = 0:0:0.50
[junit4:junit4]   2> 3841 T37 C4 UPDATE [collection1] webapp=null path=null params={synchronous=true&command=delta-import&commit=true&indent=true&clean=false&dataConfig=<dataConfig>+%0a<dataSource+name%3D"hsqldb"+driver%3D"org.hsqldb.jdbcDriver"+url%3D"jdbc:hsqldb:mem:."+/>+%0a<dataSource+name%3D"derby"+driver%3D"org.apache.derby.jdbc.EmbeddedDriver"+url%3D"jdbc:derby:memory:derbyDB;"+/>+%0a<document+name%3D"TestSqlEntityProcessor">+%0a<entity+name%3D"People"+pk%3D"ID"+processor%3D"SqlEntityProcessor"+dataSource%3D"hsqldb"+query%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+WHERE+DELETED+!%3D+'Y'+"+deletedPkQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+"+deltaImportQuery%3D"SELECT+ID,+NAME,+COUNTRY_CODE+FROM+PEOPLE+where+ID%3D${dih.delta.ID<http://dih.delta.ID>}+"+deltaQuery%3D"SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+last_modified+%26gt;%3D'${dih.last_index_time}'+UNION+DISTINCT+SELECT+ID+FROM+PEOPLE+WHERE+DELETED!%3D'Y'+AND+COUNTRY_CODE+IN+(SELECT+CODE+FROM+COUNTRIES+WHERE+last_modified+%26gt;%3D'${dih.last_index_time}')+"+>+%0a<field+column%3D"NAME"+name%3D"NAME_mult_s"+/>+%0a<field+column%3D"COUNTRY_CODE"+name%3D"COUNTRY_CODES_mult_s"+/>+%0a</entity>+%0a</document>+%0a</dataConfig>+%0a} {delete=[12, 10, 5, 20, 4, 16],add=[1008, 13, 3, 19],commit=} 0 55
[junit4:junit4]   2> 3850 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=*:*&version=2.2} hits=15 status=0 QTime=8
[junit4:junit4]   2> 3854 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 3854 T37 C4 REQ [collection1] webapp=null path=null params={indent=true} status=0 QTime=0
[junit4:junit4]   2> 3856 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:1008&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 3858 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:12&version=2.2} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3861 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:10&version=2.2} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3863 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:20&version=2.2} hits=0 status=0 QTime=0
[junit4:junit4]   2> 3866 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:5&version=2.2} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3883 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:4&version=2.2} hits=0 status=0 QTime=3
[junit4:junit4]   2> 3887 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:16&version=2.2} hits=0 status=0 QTime=1
[junit4:junit4]   2> 3890 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:3&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 3894 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:19&version=2.2} hits=1 status=0 QTime=1
[junit4:junit4]   2> 3898 T37 C4 REQ [collection1] webapp=null path=null params={rows=20&start=0&qt=standard&q=id:13&version=2.2} hits=1 status=0 QTime=0
[junit4:junit4]   2> 3902 T37 oashd.AbstractDataImportHandlerTestCase.tearDown Looking for dataimport.properties at: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/solr/collection1/conf/dataimport.properties
[junit4:junit4]   2> 3903 T37 oas.SolrTestCaseJ4.tearDown ###Ending testSingleEntity
[junit4:junit4]   2> 3914 T37 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 3915 T37 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=6099790
[junit4:junit4]   2> 3915 T37 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@7255cc
[junit4:junit4]   2> 3915 T37 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=11,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=131,cumulative_deletesById=11,cumulative_deletesByQuery=8,cumulative_errors=0}
[junit4:junit4]   2> 3916 T37 oasc.SolrCore.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 3916 T37 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 3916 T37 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 3918 T37 C4 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> 3919 T37 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 3920 T37 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/contrib/solr-dataimporthandler/test/J1/./solrtest-TestSqlEntityProcessorDelta-1354637814349/index
[junit4:junit4]   2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=ar_LB, timezone=US/Aleutian
[junit4:junit4]   2> NOTE: Linux 3.2.0-34-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=29517424,total=64880640
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestVariableResolver, TestDocBuilder2, TestSqlEntityProcessor, TestClobTransformer, TestNestedChildren, TestEphemeralCache, TestSqlEntityProcessorDelta]
[junit4:junit4] Completed on J1 in 3.96s, 4 tests, 1 error <<< FAILURES!

[...truncated 46 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:335: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:192: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:410: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:438: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1163: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:827: There were test failures: 34 suites, 140 tests, 1 error, 3 ignored

Total time: 30 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.8.0-ea-b65 -server -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org<mailto:dev-unsubscribe@lucene.apache.org>
For additional commands, e-mail: dev-help@lucene.apache.org<mailto:dev-help@lucene.apache.org>

Mime
View raw message