[ https://issues.apache.org/jira/browse/OOZIE-970?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13443705#comment-13443705 ]
Virag Kothari commented on OOZIE-970: ------------------------------------- For the failing TestLastModified.testWorkflowRun, it is the same issue in SuspendX being resolved in OOZIE-971. For TestCoordActionGetByLastModifiedTimeJPAExecutor, init() on services is being called in LocalOozie.start() also. {code} protected void setUp() throws Exception { super.setUp(); services = new Services(); services.init(); cleanUpDBTables(); LocalOozie.start(); } {code} I think we should get rid of LocalOozie.start() here to avoid any race condition. But, I am not sure whether it will fix the test case or not. > Intermittent test errors for > org.apache.oozie.command.wf.TestLastModified.testWorkflowRun and > org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor.testCoordActionGet > > ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- > > Key: OOZIE-970 > URL: https://issues.apache.org/jira/browse/OOZIE-970 > Project: Oozie > Issue Type: Bug > Components: tests > Reporter: Robert Kanter > Priority: Minor > > The org.apache.oozie.command.wf.TestLastModified.testWorkflowRun and > org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor.testCoordActionGet > tests both have errors on Apache Jenkins but I can't seem to reproduce the > errors myself (tested on mac or ubuntu). > {code:title=org.apache.oozie.command.wf.TestLastModified.testWorkflowRun} > Error Message > org.apache.oozie.DagEngineException: E0603: SQL error in operation > [<openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E], {1} > Stacktrace > E0603 : org.apache.oozie.DagEngineException: E0603: SQL error in operation > [<openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E], {1} > at org.apache.oozie.LocalOozieClient.suspend(LocalOozieClient.java:223) > at > org.apache.oozie.command.wf.TestLastModified.testWorkflowRun(TestLastModified.java:118) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at junit.framework.TestCase.runTest(TestCase.java:168) > at junit.framework.TestCase.runBare(TestCase.java:134) > at junit.framework.TestResult$1.protect(TestResult.java:110) > at junit.framework.TestResult.runProtected(TestResult.java:128) > at junit.framework.TestResult.run(TestResult.java:113) > at junit.framework.TestCase.run(TestCase.java:124) > at junit.framework.TestSuite.runTest(TestSuite.java:243) > at junit.framework.TestSuite.run(TestSuite.java:238) > at > org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83) > at > org.apache.maven.surefire.junitcore.ClassDemarcatingRunner.run(ClassDemarcatingRunner.java:58) > at org.junit.runners.Suite.runChild(Suite.java:128) > at org.junit.runners.Suite.runChild(Suite.java:24) > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) > at java.util.concurrent.FutureTask.run(FutureTask.java:138) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:619) > Caused by: org.apache.oozie.DagEngineException: E0603: SQL error in operation > [<openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E], {1} > at org.apache.oozie.DagEngine.suspend(DagEngine.java:211) > at org.apache.oozie.LocalOozieClient.suspend(LocalOozieClient.java:220) > ... 24 more > Caused by: org.apache.oozie.command.CommandException: E0603: SQL error in > operation [<openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E], {1} > at > org.apache.oozie.command.wf.SuspendXCommand.execute(SuspendXCommand.java:73) > at > org.apache.oozie.command.wf.SuspendXCommand.execute(SuspendXCommand.java:45) > at org.apache.oozie.command.XCommand.call(XCommand.java:277) > at org.apache.oozie.DagEngine.suspend(DagEngine.java:208) > ... 25 more > Caused by: org.apache.oozie.executor.jpa.JPAExecutorException: E0603: SQL > error in operation [<openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E], {1} > at > org.apache.oozie.executor.jpa.BulkUpdateInsertJPAExecutor.execute(BulkUpdateInsertJPAExecutor.java:98) > at > org.apache.oozie.executor.jpa.BulkUpdateInsertJPAExecutor.execute(BulkUpdateInsertJPAExecutor.java:32) > at org.apache.oozie.service.JPAService.execute(JPAService.java:211) > at > org.apache.oozie.command.wf.SuspendXCommand.execute(SuspendXCommand.java:66) > ... 28 more > Caused by: <openjpa-2.1.0-r422266:1071316 nonfatal store error> > org.apache.openjpa.persistence.EntityNotFoundException: The instance of type > "class org.apache.oozie.WorkflowJobBean" with oid "action1@1_E" no longer > exists in the data store. This may mean that you deleted the instance in a > separate transaction, but this context still has a cached version. > FailedObject: org.apache.oozie.WorkflowJobBean-action1@1_E > at > org.apache.openjpa.kernel.StateManagerImpl.loadFields(StateManagerImpl.java:3062) > at > org.apache.openjpa.kernel.DetachedStateManager.attach(DetachedStateManager.java:163) > at > org.apache.openjpa.kernel.AttachManager.attach(AttachManager.java:251) > at > org.apache.openjpa.kernel.AttachManager.attach(AttachManager.java:104) > at org.apache.openjpa.kernel.BrokerImpl.attach(BrokerImpl.java:3429) > at > org.apache.openjpa.kernel.DelegatingBroker.attach(DelegatingBroker.java:1206) > at > org.apache.openjpa.persistence.EntityManagerImpl.merge(EntityManagerImpl.java:869) > at > org.apache.oozie.executor.jpa.BulkUpdateInsertJPAExecutor.execute(BulkUpdateInsertJPAExecutor.java:92) > ... 31 more > Standard Output > Setting testcase work > dir[/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.command.wf.TestLastModified/testWorkflowRun] > Setting FS testcase work > dir[hdfs://localhost:43686/user/test/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.command.wf.TestLastModified/testWorkflowRun] > Running embedded servlet container at: http://janus:44091 > {code} > {code:title=org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor.testCoordActionGet} > Error Message > The transaction has been rolled back. See the nested exceptions for details > on the errors that occurred. > Stacktrace > <openjpa-2.1.0-r422266:1071316 fatal store error> > org.apache.openjpa.persistence.RollbackException: The transaction has been > rolled back. See the nested exceptions for details on the errors that > occurred. > FailedObject: org.apache.oozie.CoordinatorActionBean@2b8ca3 > at > org.apache.openjpa.persistence.EntityManagerImpl.commit(EntityManagerImpl.java:585) > at org.apache.oozie.service.JPAService.execute(JPAService.java:217) > at > org.apache.oozie.test.XDataTestCase.addRecordToCoordActionTable(XDataTestCase.java:462) > at > org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor.testCoordActionGet(TestCoordActionGetByLastModifiedTimeJPAExecutor.java:59) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at junit.framework.TestCase.runTest(TestCase.java:168) > at junit.framework.TestCase.runBare(TestCase.java:134) > at junit.framework.TestResult$1.protect(TestResult.java:110) > at junit.framework.TestResult.runProtected(TestResult.java:128) > at junit.framework.TestResult.run(TestResult.java:113) > at junit.framework.TestCase.run(TestCase.java:124) > at junit.framework.TestSuite.runTest(TestSuite.java:243) > at junit.framework.TestSuite.run(TestSuite.java:238) > at > org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83) > at > org.apache.maven.surefire.junitcore.ClassDemarcatingRunner.run(ClassDemarcatingRunner.java:58) > at org.junit.runners.Suite.runChild(Suite.java:128) > at org.junit.runners.Suite.runChild(Suite.java:24) > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) > at java.util.concurrent.FutureTask.run(FutureTask.java:138) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:619) > Caused by: <openjpa-2.1.0-r422266:1071316 fatal store error> > org.apache.openjpa.persistence.EntityExistsException: The transaction has > been rolled back. See the nested exceptions for details on the errors that > occurred. > FailedObject: org.apache.oozie.CoordinatorActionBean@2b8ca3 > at > org.apache.openjpa.kernel.BrokerImpl.newFlushException(BrokerImpl.java:2316) > at org.apache.openjpa.kernel.BrokerImpl.flush(BrokerImpl.java:2153) > at org.apache.openjpa.kernel.BrokerImpl.flushSafe(BrokerImpl.java:2051) > at > org.apache.openjpa.kernel.BrokerImpl.beforeCompletion(BrokerImpl.java:1969) > at > org.apache.openjpa.kernel.LocalManagedRuntime.commit(LocalManagedRuntime.java:81) > at org.apache.openjpa.kernel.BrokerImpl.commit(BrokerImpl.java:1493) > at > org.apache.openjpa.kernel.DelegatingBroker.commit(DelegatingBroker.java:925) > at > org.apache.openjpa.persistence.EntityManagerImpl.commit(EntityManagerImpl.java:561) > ... 26 more > Caused by: <openjpa-2.1.0-r422266:1071316 fatal store error> > org.apache.openjpa.persistence.EntityExistsException: Violation of unique > constraint $$: duplicate value(s) for column(s) $$: SYS_PK_51 in statement > [INSERT INTO COORD_ACTIONS (id, action_number, action_xml, console_url, > created_conf, error_code, error_message, external_status, > missing_dependencies, run_conf, time_out, tracker_uri, job_type, bean_type, > created_time, external_id, job_id, last_modified_time, nominal_time, pending, > rerun_time, sla_xml, status) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, > ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)] {prepstmnt 2336618 INSERT INTO COORD_ACTIONS > (id, action_number, action_xml, console_url, created_conf, error_code, > error_message, external_status, missing_dependencies, run_conf, time_out, > tracker_uri, job_type, bean_type, created_time, external_id, job_id, > last_modified_time, nominal_time, pending, rerun_time, sla_xml, status) > VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) > [params=?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?]} > [code=-104, state=23000] > FailedObject: org.apache.oozie.CoordinatorActionBean@2b8ca3 > at > org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:4854) > at > org.apache.openjpa.jdbc.sql.DBDictionary.newStoreException(DBDictionary.java:4829) > at > org.apache.openjpa.jdbc.sql.HSQLDictionary.newStoreException(HSQLDictionary.java:360) > at > org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:136) > at > org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:78) > at > org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushBatch(BatchingPreparedStatementManagerImpl.java:217) > at > org.apache.openjpa.jdbc.kernel.BatchingConstraintUpdateManager.flush(BatchingConstraintUpdateManager.java:63) > at > org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:103) > at > org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:76) > at > org.apache.openjpa.jdbc.kernel.JDBCStoreManager.flush(JDBCStoreManager.java:742) > at > org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:131) > ... 33 more > Caused by: org.apache.openjpa.lib.jdbc.ReportingSQLException: Violation of > unique constraint $$: duplicate value(s) for column(s) $$: SYS_PK_51 in > statement [INSERT INTO COORD_ACTIONS (id, action_number, action_xml, > console_url, created_conf, error_code, error_message, external_status, > missing_dependencies, run_conf, time_out, tracker_uri, job_type, bean_type, > created_time, external_id, job_id, last_modified_time, nominal_time, pending, > rerun_time, sla_xml, status) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, > ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)] {prepstmnt 2336618 INSERT INTO COORD_ACTIONS > (id, action_number, action_xml, console_url, created_conf, error_code, > error_message, external_status, missing_dependencies, run_conf, time_out, > tracker_uri, job_type, bean_type, created_time, external_id, job_id, > last_modified_time, nominal_time, pending, rerun_time, sla_xml, status) > VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) > [params=?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?]} > [code=-104, state=23000] > at > org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:281) > at > org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:257) > at > org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$1000(LoggingConnectionDecorator.java:72) > at > org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeUpdate(LoggingConnectionDecorator.java:1199) > at > org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:291) > at > org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.java:1776) > at > org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.executeUpdate(PreparedStatementManagerImpl.java:267) > at > org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushSingleRow(BatchingPreparedStatementManagerImpl.java:246) > at > org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushBatch(BatchingPreparedStatementManagerImpl.java:155) > ... 38 more > Standard Output > Setting testcase work > dir[/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor/testCoordActionGet] > Setting FS testcase work > dir[hdfs://localhost:43686/user/test/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor/testCoordActionGet] > 18:56:24,979 INFO XLogService:539 - > > ******************************************************************************* > > STARTUP MSG: Oozie BUILD_VERSION [3.3.0-SNAPSHOT] compiled by [jenkins] on > [${build.time}] > STARTUP MSG: revision [${vc.revision}]@[${vc.url}] > ******************************************************************************* > 18:56:24,979 INFO XLogService:539 - Log4j configuration file > [oozie-log4j.properties] > 18:56:24,979 INFO XLogService:539 - Log4j configuration file loaded from > [CLASSPATH] > 18:56:24,980 INFO XLogService:539 - Log4j reload interval [disabled] > 18:56:24,980 WARN XLogService:542 - Oozie WS log will be disabled, missing > property 'log4j.appender.oozie.File' for 'oozie' appender > 18:56:24,980 INFO ConfigurationService:539 - USER[test] GROUP[-] Oozie home > dir > [/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor/testCoordActionGet] > 18:56:24,980 INFO ConfigurationService:539 - USER[test] GROUP[-] Oozie conf > dir > [/home/jenkins/jenkins-slave/workspace/oozie-trunk-precommit-build/core/target/test-data/oozietests/org.apache.oozie.executor.jpa.TestCoordActionGetByLastModifiedTimeJPAExecutor/testCoordActionGet/conf] > 18:56:24,980 INFO ConfigurationService:539 - USER[test] GROUP[-] Oozie conf > file [oozie-site.xml] > 18:56:24,984 INFO ConfigurationService:539 - USER[test] GROUP[-] > Configuration change via System Property, > [oozie.service.HadoopAccessorService.supported.filesystems]=[*] > 18:56:24,984 WARN ConfigurationService:542 - USER[test] GROUP[-] System > property [oozie.action.conf.xml] no defined in Oozie configuration, ignored > 18:56:24,984 WARN ConfigurationService:542 - USER[test] GROUP[-] System > property [oozie.action.newId.properties] no defined in Oozie configuration, > ignored > 18:56:24,984 WARN Services:542 - USER[test] GROUP[-] System ID [oozie-jenk] > exceeds maximum length [10], trimming > 18:56:24,985 INFO Services:539 - USER[test] GROUP[-] Exiting null Entering > NORMAL > 18:56:24,985 INFO Services:539 - USER[test] GROUP[-] Initialized runtime > directory [/tmp/oozie-jenk2819998336030098143.dir] > 18:56:24,987 WARN ConfigurationService:542 - USER[test] GROUP[-] > Configuration property [oozie.service.ELService.ext.constants.job-submit] not > found, using default [] > 18:56:24,987 WARN ConfigurationService:542 - USER[test] GROUP[-] > Configuration property [oozie.service.ELService.ext.functions.job-submit] not > found, using default [] > 18:56:24,990 WARN ConfigurationService:542 - USER[test] GROUP[-] > Configuration property [oozie.service.AuthorizationService.security.enabled] > not found, using default [null] > 18:56:24,990 WARN AuthorizationService:542 - USER[test] GROUP[-] Oozie > running with authorization disabled > 18:56:24,990 INFO HadoopAccessorService:539 - USER[test] GROUP[-] > JOB_TRACKER_WHITELIST :[ ], Total entries :0 > 18:56:24,990 INFO HadoopAccessorService:539 - USER[test] GROUP[-] > NAME_NODE_WHITELIST :[ ], Total entries :0 > 18:56:24,990 INFO HadoopAccessorService:539 - USER[test] GROUP[-] Oozie > Kerberos Authentication [disabled] > 18:56:25,109 INFO JPAService:539 - USER[test] GROUP[-] TOKEN[testToken] > APP[testApp] JOB[0000000-120824185624718-oozie-jenk-W] ACTION[-] All entities > initialized > 18:56:25,110 INFO JPAService:539 - USER[test] GROUP[-] TOKEN[testToken] > APP[testApp] JOB[0000000-120824185624718-oozie-jenk-W] ACTION[-] JPA > configuration: > DriverClassName=org.hsqldb.jdbcDriver,Url=jdbc:hsqldb:mem:oozie-db;create=true,Username=sa,Password=***,MaxActive=10,TestOnBorrow=false,TestOnReturn=false,TestWhileIdle=false > 18:56:25,140 INFO Services:539 - Initialized > 18:56:25,141 INFO Services:539 - Running with JARs for Hadoop version [1.0.1] > 18:56:25,141 INFO Services:539 - Oozie System ID [oozie-jenk] started! > 18:56:25,147 WARN Services:542 - USER[test] GROUP[-] TOKEN[testToken] > APP[testApp] JOB[0000000-120824185624718-oozie-jenk-W] ACTION[-] Previous > services singleton active, destroying it > 18:56:25,148 INFO Services:539 - Shutdown > Running embedded servlet container at: http://janus:39195 > {code} -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira