Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Pending Closed
    • Affects Version/s: None
    • Fix Version/s: 14.12.01, 12.04.06, 13.07.03, 16.11.01
    • Component/s: None
    • Labels:
      None

      Description

      Details in comments.

      1. OFBIZ-6218.patch
        2 kB
        Nicolas Malin

        Issue Links

          Activity

          Hide
          adrianc@hlmksw.com Adrian Crum added a comment -

          Test output:

          <testsuite errors="1" failures="0" hostname="speed-demon" id="20" name="performfindtests" package="" skipped="0" tests="5" time="0.345" timestamp="2015-03-27T09:56:46"><properties/><testcase classname="org.ofbiz.common.test.PerformFindTests" name="testPerformFindConditionDistinct" time="0.096"><error type="java.lang.NullPointerException">java.lang.NullPointerException
          	at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235)
          	at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218)
          	at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166)
          	at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235)
          	at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154)
          	at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329)
          	at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436)
          	at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49)
          	at org.ofbiz.common.test.PerformFindTests.testPerformFindConditionDistinct(PerformFindTests.java:190)
          	at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146)
          	at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237)
          	at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342)
          	at org.ofbiz.base.start.Start.start(Start.java:368)
          	at org.ofbiz.base.start.Start.main(Start.java:135)
          </error></testcase><testcase classname="org.ofbiz.common.test.PerformFindTests" name="testPerformFindConditionFieldLike" time="0.062"/><testcase classname="org.ofbiz.common.test.PerformFindTests" name="testPerformFindConditionFieldEquals" time="0.067"/><testcase classname="org.ofbiz.common.test.PerformFindTests" name="testPerformFindFilterByDateWithDedicateDateField" time="0.057"/><testcase classname="org.ofbiz.common.test.PerformFindTests" name="testPerformFindFilterByDate" time="0.045"/></testsuite>
          
          Show
          adrianc@hlmksw.com Adrian Crum added a comment - Test output: <testsuite errors= "1" failures= "0" hostname= "speed-demon" id= "20" name= "performfindtests" package = "" skipped=" 0 " tests=" 5 " time=" 0.345 " timestamp=" 2015-03-27T09:56:46 "><properties/><testcase classname=" org.ofbiz.common.test.PerformFindTests " name=" testPerformFindConditionDistinct " time=" 0.096 "><error type=" java.lang.NullPointerException">java.lang.NullPointerException at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154) at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329) at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436) at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) at org.ofbiz.common.test.PerformFindTests.testPerformFindConditionDistinct(PerformFindTests.java:190) at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342) at org.ofbiz.base.start.Start.start(Start.java:368) at org.ofbiz.base.start.Start.main(Start.java:135) </error></testcase><testcase classname= "org.ofbiz.common.test.PerformFindTests" name= "testPerformFindConditionFieldLike" time= "0.062" /><testcase classname= "org.ofbiz.common.test.PerformFindTests" name= "testPerformFindConditionFieldEquals" time= "0.067" /><testcase classname= "org.ofbiz.common.test.PerformFindTests" name= "testPerformFindFilterByDateWithDedicateDateField" time= "0.057" /><testcase classname= "org.ofbiz.common.test.PerformFindTests" name= "testPerformFindFilterByDate" time= "0.045" /></testsuite>
          Hide
          adrianc@hlmksw.com Adrian Crum added a comment -
          2015-03-27 10:43:12,491 |main                 |EntityListIterator            |W| Exception thrown while calling ResultSet.next(): 
          java.sql.SQLException: ResultSet not open. Operation 'next' not permitted. Verify that autocommit is off.
          	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.EmbedConnection.newSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.ConnectionChild.newSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.EmbedResultSet.checkIfClosed(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.EmbedResultSet.checkExecIfClosed(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) ~[commons-dbcp2-2.1.jar:2.1]
          	at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) ~[commons-dbcp2-2.1.jar:2.1]
          	at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:321) [ofbiz-entity.jar:?]
          	at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:437) [ofbiz-entity.jar:?]
          	at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) [ofbiz-common-test.jar:?]
          	at org.ofbiz.common.test.PerformFindTests.testPerformFindFilterByDateWithDedicateDateField(PerformFindTests.java:232) [ofbiz-common-test.jar:?]
          	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_60]
          	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_60]
          	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_60]
          	at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_60]
          	at junit.framework.TestCase.runTest(TestCase.java:168) [junit-dep-4.10.jar:?]
          	at junit.framework.TestCase.runBare(TestCase.java:134) [junit-dep-4.10.jar:?]
          	at junit.framework.TestResult$1.protect(TestResult.java:110) [junit-dep-4.10.jar:?]
          	at junit.framework.TestResult.runProtected(TestResult.java:128) [junit-dep-4.10.jar:?]
          	at junit.framework.TestResult.run(TestResult.java:113) [junit-dep-4.10.jar:?]
          	at junit.framework.TestCase.run(TestCase.java:124) [junit-dep-4.10.jar:?]
          	at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?]
          	at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?]
          	at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?]
          	at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?]
          	at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) [ofbiz-testtools.jar:?]
          	at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) [ofbiz-base.jar:?]
          	at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342) [ofbiz.jar:?]
          	at org.ofbiz.base.start.Start.start(Start.java:368) [ofbiz.jar:?]
          	at org.ofbiz.base.start.Start.main(Start.java:135) [ofbiz.jar:?]
          Caused by: org.apache.derby.iapi.error.StandardException: ResultSet not open. Operation 'next' not permitted. Verify that autocommit is off.
          	at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	at org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown Source) ~[derby-10.11.1.1.jar:?]
          	... 35 more
          

          It appears the ResultSet is being closed prematurely somehow.

          Show
          adrianc@hlmksw.com Adrian Crum added a comment - 2015-03-27 10:43:12,491 |main |EntityListIterator |W| Exception thrown while calling ResultSet.next(): java.sql.SQLException: ResultSet not open. Operation 'next' not permitted. Verify that autocommit is off. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.EmbedConnection.newSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.ConnectionChild.newSQLException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.EmbedResultSet.checkIfClosed(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.EmbedResultSet.checkExecIfClosed(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) ~[commons-dbcp2-2.1.jar:2.1] at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) ~[commons-dbcp2-2.1.jar:2.1] at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:321) [ofbiz-entity.jar:?] at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:437) [ofbiz-entity.jar:?] at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) [ofbiz-common-test.jar:?] at org.ofbiz.common.test.PerformFindTests.testPerformFindFilterByDateWithDedicateDateField(PerformFindTests.java:232) [ofbiz-common-test.jar:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_60] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_60] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_60] at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_60] at junit.framework.TestCase.runTest(TestCase.java:168) [junit-dep-4.10.jar:?] at junit.framework.TestCase.runBare(TestCase.java:134) [junit-dep-4.10.jar:?] at junit.framework.TestResult$1.protect(TestResult.java:110) [junit-dep-4.10.jar:?] at junit.framework.TestResult.runProtected(TestResult.java:128) [junit-dep-4.10.jar:?] at junit.framework.TestResult.run(TestResult.java:113) [junit-dep-4.10.jar:?] at junit.framework.TestCase.run(TestCase.java:124) [junit-dep-4.10.jar:?] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?] at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) [ofbiz-testtools.jar:?] at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) [ofbiz-base.jar:?] at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342) [ofbiz.jar:?] at org.ofbiz.base.start.Start.start(Start.java:368) [ofbiz.jar:?] at org.ofbiz.base.start.Start.main(Start.java:135) [ofbiz.jar:?] Caused by: org.apache.derby.iapi.error.StandardException: ResultSet not open. Operation 'next' not permitted. Verify that autocommit is off. at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) ~[derby-10.11.1.1.jar:?] at org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown Source) ~[derby-10.11.1.1.jar:?] ... 35 more It appears the ResultSet is being closed prematurely somehow.
          Hide
          pfm.smits Pierre Smits added a comment - - edited

          This might be related to something I am experiencing with a piece of groovy code:

          rolesIter = partyRelationRoles.iterator()
          while (rolesIter){
          thisItem = rolesIter.next()
          partyNameView = delegator.findOne("PartyNameView",["partyId" : thisItem.partyIdFrom], false)
          }
          
          

          Which results in following log messages:

               [java] 2015-03-28 21:33:36,303 |http-bio-8443-exec-7 |                              |I| in community, getRoles:org.ofbiz.entity.util.EntityListIterator@12f4bdac
               [java] 2015-03-28 21:33:36,303 |http-bio-8443-exec-7 |EntityListIterator            |W| For performance reasons do not use the EntityListIterator.hasNext() method, just call next() until it returns null; see JavaDoc comments in the EntityListIterator class for details and an example
               [java] java.lang.Exception
               [java] at org.ofbiz.entity.util.EntityListIterator.hasNext(EntityListIterator.java:254) [ofbiz-entity.jar:?]
               [java] at org.codehaus.groovy.runtime.DefaultGroovyMethods.asBoolean(DefaultGroovyMethods.java:7781) [groovy-all-2.2.1.jar:2.2.1]
               [java] at org.codehaus.groovy.runtime.dgm$28.doMethodInvoke(Unknown Source) [groovy-all-2.2.1.jar:2.2.1]
               [java] at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1085) [groovy-all-2.2.1.jar:2.2.1]
          

          followed by:

               [java] 2015-03-28 21:36:39,424 |Finalizer            |EntityListIterator            |E| 
               [java] ====================================================================
               [java]  EntityListIterator Not Closed for Entity [PartyRelationship], caught in Finalize
               [java]  ====================================================================
               [java] 
               [java] 2015-03-28 21:36:39,425 |Finalizer            |SQLProcessor                  |E| Error closing the result, connection, etc in finalize SQLProcessor
               [java] java.lang.NullPointerException
               [java] 	at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) ~[commons-dbcp2-2.1.jar:2.1]
               [java] 	at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) ~[commons-dbcp2-2.1.jar:2.1]
               [java] 	at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) ~[commons-dbcp2-2.1.jar:2.1]
               [java] 	at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) ~[ofbiz-entity.jar:?]
               [java] 	at org.ofbiz.entity.jdbc.SQLProcessor.finalize(SQLProcessor.java:844) [ofbiz-entity.jar:?]
               [java] 	at java.lang.System$2.invokeFinalize(System.java:1213) [?:1.7.0_71]
               [java] 	at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98) [?:1.7.0_71]
               [java] 	at java.lang.ref.Finalizer.access$100(Finalizer.java:34) [?:1.7.0_71]
               [java] 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210) [?:1.7.0_71]
          
          Show
          pfm.smits Pierre Smits added a comment - - edited This might be related to something I am experiencing with a piece of groovy code: rolesIter = partyRelationRoles.iterator() while (rolesIter){ thisItem = rolesIter.next() partyNameView = delegator.findOne( "PartyNameView" ,[ "partyId" : thisItem.partyIdFrom], false ) } Which results in following log messages: [java] 2015-03-28 21:33:36,303 |http-bio-8443-exec-7 | |I| in community, getRoles:org.ofbiz.entity.util.EntityListIterator@12f4bdac [java] 2015-03-28 21:33:36,303 |http-bio-8443-exec-7 |EntityListIterator |W| For performance reasons do not use the EntityListIterator.hasNext() method, just call next() until it returns null ; see JavaDoc comments in the EntityListIterator class for details and an example [java] java.lang.Exception [java] at org.ofbiz.entity.util.EntityListIterator.hasNext(EntityListIterator.java:254) [ofbiz-entity.jar:?] [java] at org.codehaus.groovy.runtime.DefaultGroovyMethods.asBoolean(DefaultGroovyMethods.java:7781) [groovy-all-2.2.1.jar:2.2.1] [java] at org.codehaus.groovy.runtime.dgm$28.doMethodInvoke(Unknown Source) [groovy-all-2.2.1.jar:2.2.1] [java] at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1085) [groovy-all-2.2.1.jar:2.2.1] followed by: [java] 2015-03-28 21:36:39,424 |Finalizer |EntityListIterator |E| [java] ==================================================================== [java] EntityListIterator Not Closed for Entity [PartyRelationship], caught in Finalize [java] ==================================================================== [java] [java] 2015-03-28 21:36:39,425 |Finalizer |SQLProcessor |E| Error closing the result, connection, etc in finalize SQLProcessor [java] java.lang.NullPointerException [java] at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) ~[commons-dbcp2-2.1.jar:2.1] [java] at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) ~[commons-dbcp2-2.1.jar:2.1] [java] at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) ~[commons-dbcp2-2.1.jar:2.1] [java] at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) ~[ofbiz-entity.jar:?] [java] at org.ofbiz.entity.jdbc.SQLProcessor.finalize(SQLProcessor.java:844) [ofbiz-entity.jar:?] [java] at java.lang. System $2.invokeFinalize( System .java:1213) [?:1.7.0_71] [java] at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98) [?:1.7.0_71] [java] at java.lang.ref.Finalizer.access$100(Finalizer.java:34) [?:1.7.0_71] [java] at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210) [?:1.7.0_71]
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Got similar than Adrian, see http://markmail.org/message/fez6pcbgki4twslt

          Show
          jacques.le.roux Jacques Le Roux added a comment - Got similar than Adrian, see http://markmail.org/message/fez6pcbgki4twslt
          Hide
          soledad Nicolas Malin added a comment - - edited

          At the beginning I wrote these unit tests to check the performFind not the database pool !

          After run many test like this : **while true; do ./ant run-test-suite -Dtest.component=common -Dtest.suiteName=performfindtests; sleep 10; done;** , I have the following result :

          • on derby : 30% test failed
          • on postgresql : 60% test failed

          I didn't found any reason.

          Show
          soledad Nicolas Malin added a comment - - edited At the beginning I wrote these unit tests to check the performFind not the database pool ! After run many test like this : ** while true; do ./ant run-test-suite -Dtest.component=common -Dtest.suiteName=performfindtests; sleep 10; done; ** , I have the following result : on derby : 30% test failed on postgresql : 60% test failed I didn't found any reason.
          Hide
          adrianc@hlmksw.com Adrian Crum added a comment -

          Nicolas,

          No one is blaming the tests. Here is what we know:

          1. DBCP is used in most of our unit tests, but only fails in the performFind tests.

          2. Different find tests fail, but a failure is guaranteed in one of them (on my machine), and a failure is repeatable (on your machine).

          3. One thing that is common to all failing tests is the use of EntityListIterator. I started looking into it to see if a code path in ELI can prematurely close the connection, but I ran out of time.

          Right now my gut feeling is that this is not a problem in DBCP, but in our code.

          Show
          adrianc@hlmksw.com Adrian Crum added a comment - Nicolas, No one is blaming the tests. Here is what we know: 1. DBCP is used in most of our unit tests, but only fails in the performFind tests. 2. Different find tests fail, but a failure is guaranteed in one of them (on my machine), and a failure is repeatable (on your machine). 3. One thing that is common to all failing tests is the use of EntityListIterator. I started looking into it to see if a code path in ELI can prematurely close the connection, but I ran out of time. Right now my gut feeling is that this is not a problem in DBCP, but in our code.
          Hide
          soledad Nicolas Malin added a comment - - edited

          I blame these tests myself !

          Right now my gut feeling is that this is not a problem in DBCP, but in our code.

          I know that, and it's THE problem because I don't understand where is the beast to kill.

          To simplify the code reading, I create a private function

              private List<GenericValue> getCompleteList(Map<String, Object> context) {
                  EntityListIterator listIt = (EntityListIterator) context.get("listIt");
                  List<GenericValue> foundElements = new LinkedList<GenericValue>();
                  if (listIt != null) {
                      try {
                          foundElements = listIt.getCompleteList();
                      } catch (GenericEntityException e) {
                          Debug.logError(" Failed to extract values from EntityListIterator after a performFind service", module);
                      } finally {
                          try {
                              listIt.close();
                          } catch (GenericEntityException e) {
                              Debug.logError(" Failed to close EntityListIterator after a performFind service", module);
                          }
                      }
                  }
                  return foundElements;
              }
          

          It's the only location where I use an EntityListIterator in performFind tests

          Show
          soledad Nicolas Malin added a comment - - edited I blame these tests myself ! Right now my gut feeling is that this is not a problem in DBCP, but in our code. I know that, and it's THE problem because I don't understand where is the beast to kill. To simplify the code reading, I create a private function private List<GenericValue> getCompleteList(Map< String , Object > context) { EntityListIterator listIt = (EntityListIterator) context.get( "listIt" ); List<GenericValue> foundElements = new LinkedList<GenericValue>(); if (listIt != null ) { try { foundElements = listIt.getCompleteList(); } catch (GenericEntityException e) { Debug.logError( " Failed to extract values from EntityListIterator after a performFind service" , module); } finally { try { listIt.close(); } catch (GenericEntityException e) { Debug.logError( " Failed to close EntityListIterator after a performFind service" , module); } } } return foundElements; } It's the only location where I use an EntityListIterator in performFind tests
          Hide
          adrianc@hlmksw.com Adrian Crum added a comment -

          Pierre,

          Your errors are not related to this issue. You are seeing those log entries because EntityListIterator is being used improperly in your Groovy code.

          Show
          adrianc@hlmksw.com Adrian Crum added a comment - Pierre, Your errors are not related to this issue. You are seeing those log entries because EntityListIterator is being used improperly in your Groovy code.
          Hide
          soledad Nicolas Malin added a comment -

          Ok, after several tests (refactoring tests, trace EntityListIterator's life, add wait time, ...) I didn't found the problem.

          Offended, I create an unique test function that call each test :

          mnicolas@meno:~/workspace/ofbiz-trunk-2$ while true; do ./ant run-test-suite -Dtest.component=common -Dtest.suiteName=performfindtests | grep BUILD; done 
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          BUILD SUCCESSFUL
          

          AHHHHHHHHHH (I'm not crazy, just tired). It's works.
          So I didn't found the root cause, just a solution to remove the random error

          Show
          soledad Nicolas Malin added a comment - Ok, after several tests (refactoring tests, trace EntityListIterator's life, add wait time, ...) I didn't found the problem. Offended, I create an unique test function that call each test : mnicolas@meno:~/workspace/ofbiz-trunk-2$ while true ; do ./ant run-test-suite -Dtest.component=common -Dtest.suiteName=performfindtests | grep BUILD; done BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL BUILD SUCCESSFUL AHHHHHHHHHH (I'm not crazy, just tired). It's works. So I didn't found the root cause, just a solution to remove the random error
          Hide
          soledad Nicolas Malin added a comment -

          I commit on trunk revision 1673269 to escape the random error.

          Adrian do you want keep the issue open, to find the root cause ?

          Show
          soledad Nicolas Malin added a comment - I commit on trunk revision 1673269 to escape the random error. Adrian do you want keep the issue open, to find the root cause ?
          Hide
          adrianc@hlmksw.com Adrian Crum added a comment -

          The tests pass on my computer also. Thank you for working on this!

          Show
          adrianc@hlmksw.com Adrian Crum added a comment - The tests pass on my computer also. Thank you for working on this!
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Thanks Nicolas, indeed remains the question about the root cause. I think we should start a thread on dev ML, or here if people prefer?

          Show
          jacques.le.roux Jacques Le Roux added a comment - Thanks Nicolas, indeed remains the question about the root cause. I think we should start a thread on dev ML, or here if people prefer?
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Ha forgot to say, it's successful here also (Win7)

          Show
          jacques.le.roux Jacques Le Roux added a comment - Ha forgot to say, it's successful here also (Win7)
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Not sure it's related (it's late) found this on last Buildbot run: http://ci.apache.org/projects/ofbiz/logs/trunk/html/

          performfindtests	testPerformFind	Error	N/A
          
          java.lang.NullPointerException
          at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235)
          at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218)
          at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166)
          at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235)
          at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154)
          at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329)
          at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436)
          at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49)
          at org.ofbiz.common.test.PerformFindTests.performFindConditionFieldEquals(PerformFindTests.java:136)
          at org.ofbiz.common.test.PerformFindTests.testPerformFind(PerformFindTests.java:113)
          at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146)
          at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237)
          at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342)
          at org.ofbiz.base.start.Start.start(Start.java:368)
          at org.ofbiz.base.start.Start.main(Start.java:135)
          
          Show
          jacques.le.roux Jacques Le Roux added a comment - Not sure it's related (it's late) found this on last Buildbot run: http://ci.apache.org/projects/ofbiz/logs/trunk/html/ performfindtests testPerformFind Error N/A java.lang.NullPointerException at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154) at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329) at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436) at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) at org.ofbiz.common.test.PerformFindTests.performFindConditionFieldEquals(PerformFindTests.java:136) at org.ofbiz.common.test.PerformFindTests.testPerformFind(PerformFindTests.java:113) at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) at org.ofbiz.base.start.Start.startStartLoaders(Start.java:342) at org.ofbiz.base.start.Start.start(Start.java:368) at org.ofbiz.base.start.Start.main(Start.java:135)
          Hide
          soledad Nicolas Malin added a comment -

          Jacques I'm sure It's a joke I don't believed it !

          http://ci.apache.org/projects/ofbiz/logs/trunk/html/20_performfindtests.html

          It isn't nice to play with my nerves

          Show
          soledad Nicolas Malin added a comment - Jacques I'm sure It's a joke I don't believed it ! http://ci.apache.org/projects/ofbiz/logs/trunk/html/20_performfindtests.html It isn't nice to play with my nerves
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Yes, you can forget it, it passed lastly http://ci.apache.org/projects/ofbiz/logs/trunk/html/

          Show
          jacques.le.roux Jacques Le Roux added a comment - Yes, you can forget it, it passed lastly http://ci.apache.org/projects/ofbiz/logs/trunk/html/
          Hide
          mbrohl Michael Brohl added a comment -

          I have a problem with it locally, running the tests inside Eclipse:

          clean-all
          load-demo
          run-tests

          [java] 2015-05-19 15:00:50,463 |main |TestRunContainer |W| [JUNIT (error)] - testPerformFind : java.lang.NullPointerException
          [java] java.lang.NullPointerException
          [java] at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) ~[commons-dbcp2-2.1.jar:2.1]
          [java] at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) ~[commons-dbcp2-2.1.jar:2.1]
          [java] at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) ~[commons-dbcp2-2.1.jar:2.1]
          [java] at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) ~[ofbiz-entity.jar:?]
          [java] at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154) ~[ofbiz-entity.jar:?]
          [java] at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329) ~[ofbiz-entity.jar:?]
          [java] at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436) ~[ofbiz-entity.jar:?]
          [java] at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) ~[ofbiz-common-test.jar:?]
          [java] at org.ofbiz.common.test.PerformFindTests.performFindConditionFieldEquals(PerformFindTests.java:136) ~[ofbiz-common-test.jar:?]
          [java] at org.ofbiz.common.test.PerformFindTests.testPerformFind(PerformFindTests.java:113) ~[ofbiz-common-test.jar:?]
          [java] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_71]
          [java] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_71]
          [java] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_71]
          [java] at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_71]
          [java] at junit.framework.TestCase.runTest(TestCase.java:168) ~[junit-dep-4.10.jar:?]
          [java] at junit.framework.TestCase.runBare(TestCase.java:134) ~[junit-dep-4.10.jar:?]
          [java] at junit.framework.TestResult$1.protect(TestResult.java:110) ~[junit-dep-4.10.jar:?]
          [java] at junit.framework.TestResult.runProtected(TestResult.java:128) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestResult.run(TestResult.java:113) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestCase.run(TestCase.java:124) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?]
          [java] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?]
          [java] at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) [ofbiz-testtools.jar:?]
          [java] at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) [ofbiz-base.jar:?]
          [java] at org.ofbiz.base.start.Start.startStartLoaders(Start.java:408) [ofbiz.jar:?]
          [java] at org.ofbiz.base.start.Start.start(Start.java:434) [ofbiz.jar:?]
          [java] at org.ofbiz.base.start.Start.main(Start.java:135) [ofbiz.jar:?]
          [java] 2015-05-19 15:00:50,472 |main |TestRunContainer |I| [JUNIT] : testPerformFind finished.
          [java] 2015-05-19 15:00:50,472 |main |GenericDelegator |I| Rolling back 21 entity operations
          [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] Results for test suite: performfindtests
          [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] Pass: false | # Tests: 1 | # Failed: 0 # Errors: 1
          [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] ----------------------------- ERRORS ----------------------------- [JUNIT]

          Show
          mbrohl Michael Brohl added a comment - I have a problem with it locally, running the tests inside Eclipse: clean-all load-demo run-tests [java] 2015-05-19 15:00:50,463 |main |TestRunContainer |W| [JUNIT (error)] - testPerformFind : java.lang.NullPointerException [java] java.lang.NullPointerException [java] at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:235) ~ [commons-dbcp2-2.1.jar:2.1] [java] at org.apache.commons.dbcp2.DelegatingConnection.close(DelegatingConnection.java:218) ~ [commons-dbcp2-2.1.jar:2.1] [java] at org.apache.commons.dbcp2.managed.ManagedConnection.close(ManagedConnection.java:166) ~ [commons-dbcp2-2.1.jar:2.1] [java] at org.ofbiz.entity.jdbc.SQLProcessor.close(SQLProcessor.java:235) ~ [ofbiz-entity.jar:?] [java] at org.ofbiz.entity.util.EntityListIterator.close(EntityListIterator.java:154) ~ [ofbiz-entity.jar:?] [java] at org.ofbiz.entity.util.EntityListIterator.next(EntityListIterator.java:329) ~ [ofbiz-entity.jar:?] [java] at org.ofbiz.entity.util.EntityListIterator.getCompleteList(EntityListIterator.java:436) ~ [ofbiz-entity.jar:?] [java] at org.ofbiz.common.test.PerformFindTests.getCompleteList(PerformFindTests.java:49) ~ [ofbiz-common-test.jar:?] [java] at org.ofbiz.common.test.PerformFindTests.performFindConditionFieldEquals(PerformFindTests.java:136) ~ [ofbiz-common-test.jar:?] [java] at org.ofbiz.common.test.PerformFindTests.testPerformFind(PerformFindTests.java:113) ~ [ofbiz-common-test.jar:?] [java] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~ [?:1.7.0_71] [java] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~ [?:1.7.0_71] [java] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~ [?:1.7.0_71] [java] at java.lang.reflect.Method.invoke(Method.java:606) ~ [?:1.7.0_71] [java] at junit.framework.TestCase.runTest(TestCase.java:168) ~ [junit-dep-4.10.jar:?] [java] at junit.framework.TestCase.runBare(TestCase.java:134) ~ [junit-dep-4.10.jar:?] [java] at junit.framework.TestResult$1.protect(TestResult.java:110) ~ [junit-dep-4.10.jar:?] [java] at junit.framework.TestResult.runProtected(TestResult.java:128) [junit-dep-4.10.jar:?] [java] at junit.framework.TestResult.run(TestResult.java:113) [junit-dep-4.10.jar:?] [java] at junit.framework.TestCase.run(TestCase.java:124) [junit-dep-4.10.jar:?] [java] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?] [java] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?] [java] at junit.framework.TestSuite.runTest(TestSuite.java:243) [junit-dep-4.10.jar:?] [java] at junit.framework.TestSuite.run(TestSuite.java:238) [junit-dep-4.10.jar:?] [java] at org.ofbiz.testtools.TestRunContainer.start(TestRunContainer.java:146) [ofbiz-testtools.jar:?] [java] at org.ofbiz.base.container.ContainerLoader.start(ContainerLoader.java:237) [ofbiz-base.jar:?] [java] at org.ofbiz.base.start.Start.startStartLoaders(Start.java:408) [ofbiz.jar:?] [java] at org.ofbiz.base.start.Start.start(Start.java:434) [ofbiz.jar:?] [java] at org.ofbiz.base.start.Start.main(Start.java:135) [ofbiz.jar:?] [java] 2015-05-19 15:00:50,472 |main |TestRunContainer |I| [JUNIT] : testPerformFind finished. [java] 2015-05-19 15:00:50,472 |main |GenericDelegator |I| Rolling back 21 entity operations [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] Results for test suite: performfindtests [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] Pass: false | # Tests: 1 | # Failed: 0 # Errors: 1 [java] 2015-05-19 15:00:50,481 |main |TestRunContainer |I| [JUNIT] ----------------------------- ERRORS ----------------------------- [JUNIT]
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          I guess you used trunk HEAD w/o any changes? Then we need to continue investigating why this is still happening from time to time :/

          Show
          jacques.le.roux Jacques Le Roux added a comment - I guess you used trunk HEAD w/o any changes? Then we need to continue investigating why this is still happening from time to time :/
          Hide
          mbrohl Michael Brohl added a comment -

          Yes, trunk HEAD but with the change for OFBIZ-6258 to test the patch.

          I will later test again on command line and Eclipse without any changes.

          Show
          mbrohl Michael Brohl added a comment - Yes, trunk HEAD but with the change for OFBIZ-6258 to test the patch. I will later test again on command line and Eclipse without any changes.
          Hide
          soledad Nicolas Malin added a comment - - edited

          I just tried directly on shell with ant clean-all load-demo run-tests, without error ... strange.

          Show
          soledad Nicolas Malin added a comment - - edited I just tried directly on shell with ant clean-all load-demo run-tests , without error ... strange.
          Hide
          fbr@14x.net Forrest Rae added a comment -

          It's very likely that these strange errors are related to groovy scripts throwing exceptions that don't have error messages. One strong possibility is java.util.ConcurrentModificationException. I ran into this issue and ended up tracking it down to the lack of exception reporting in the GroovyScriptEngine: OFBIZ-6888.

          Show
          fbr@14x.net Forrest Rae added a comment - It's very likely that these strange errors are related to groovy scripts throwing exceptions that don't have error messages. One strong possibility is java.util.ConcurrentModificationException. I ran into this issue and ended up tracking it down to the lack of exception reporting in the GroovyScriptEngine: OFBIZ-6888 .
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          Thanks Forrest, I'll have a look... soon...

          Show
          jacques.le.roux Jacques Le Roux added a comment - Thanks Forrest, I'll have a look... soon...
          Hide
          jacques.le.roux Jacques Le Roux added a comment -

          I have committed the fix for OFBIZ-6888 in all supported places. I close here, we will reopen or create a new Jira issue when we will have more detailled information

          Show
          jacques.le.roux Jacques Le Roux added a comment - I have committed the fix for OFBIZ-6888 in all supported places. I close here, we will reopen or create a new Jira issue when we will have more detailled information

            People

            • Assignee:
              jacques.le.roux Jacques Le Roux
              Reporter:
              adrianc@hlmksw.com Adrian Crum
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development