You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tajo.apache.org by "Hyunsik Choi (JIRA)" <ji...@apache.org> on 2014/10/27 05:47:35 UTC
[jira] [Updated] (TAJO-1138)
TestKillQuery.testKillQueryFromInitState fails occasionally.
[ https://issues.apache.org/jira/browse/TAJO-1138?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Hyunsik Choi updated TAJO-1138:
-------------------------------
Description:
See the following logs:
{noformat}
2014-10-26 21:42:27,889 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(731)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1414384947749_0000_000001
2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (listStatus(414)) - Total input paths to process : 1
2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (getSplits(643)) - Total # of splits: 1
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.SubQuery (run(691)) - 1 objects are scheduled
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type KILL
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(89)) - Start TaskScheduler
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(148)) - Task Scheduler stopped
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_RUNNING to QUERY_KILL_WAIT
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (handle(244)) - ta_1414384947749_0000_000001_000000_00 is canceled from DefaultTaskScheduler
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(107)) - TaskScheduler schedulingThread stopped
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.QueryUnitAttempt (transition(326)) - ta_1414384947749_0000_000001_000000_00 Received TA_KILLED Status from LocalTask
2014-10-26 21:42:27,893 ERROR: org.apache.tajo.master.querymaster.SubQuery (run(704)) - SubQuery (eb_1414384947749_0000_000001) ERROR:
org.apache.hadoop.service.ServiceStateException: org.apache.tajo.master.DefaultTaskScheduler cannot enter state STARTED from state STOPPED
at org.apache.hadoop.service.ServiceStateModel.checkStateTransition(ServiceStateModel.java:129)
at org.apache.hadoop.service.ServiceStateModel.enterState(ServiceStateModel.java:111)
at org.apache.hadoop.service.AbstractService.start(AbstractService.java:190)
at org.apache.tajo.master.DefaultTaskScheduler.start(DefaultTaskScheduler.java:112)
at org.apache.tajo.master.querymaster.SubQuery$InitAndRequestContainer$1.run(SubQuery.java:697)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1132)) - [eb_1414384947749_0000_000001] Task Completion Event (Total: 1, Success: 0, Killed: 1, Failed: 0)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1234)) - subQuery completed - eb_1414384947749_0000_000001 (total=1, success=0, killed=1)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.QueryMaster (cleanupExecutionBlock(185)) - cleanup executionBlocks:
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_KILL_WAIT to QUERY_ERROR
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
2014-10-26 21:42:27,894 ERROR: org.apache.tajo.master.querymaster.Query (handle(960)) - Can't handle this event at current state, type:EventType: QUERY_COMPLETED, oldState:QUERY_ERROR, nextState:QUERY_ERROR
org.apache.hadoop.yarn.state.InvalidStateTransitonException: Invalid event: QUERY_COMPLETED at QUERY_ERROR
at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:305)
at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
at org.apache.tajo.master.querymaster.Query.handle(Query.java:957)
at org.apache.tajo.master.querymaster.Query.handle(Query.java:63)
at org.apache.tajo.master.TajoAsyncDispatcher.dispatch(TajoAsyncDispatcher.java:137)
at org.apache.tajo.master.TajoAsyncDispatcher$1.run(TajoAsyncDispatcher.java:79)
at java.lang.Thread.run(Thread.java:744)
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type INTERNAL_ERROR
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 2.56 sec <<< FAILURE! - in org.apache.tajo.master.querymaster.TestKillQuery
testKillQueryFromInitState(org.apache.tajo.master.querymaster.TestKillQuery) Time elapsed: 2.56 sec <<< FAILURE!
java.lang.AssertionError: expected:<QUERY_KILLED> but was:<QUERY_ERROR>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at org.apache.tajo.master.querymaster.TestKillQuery.testKillQueryFromInitState(TestKillQuery.java:104)
Running org.apache.tajo.master.querymaster.TestQueryProgress
2014-10-26 21:42:30,183 INFO: org.apache.tajo.master.session.SessionManager (createSession(73)) - Session 3107d08d-ff44-48f2-9daa-ce368d786167 is created.
{noformat}
was:
{noformat}
2014-10-26 21:42:27,889 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(731)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1414384947749_0000_000001
2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (listStatus(414)) - Total input paths to process : 1
2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (getSplits(643)) - Total # of splits: 1
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.SubQuery (run(691)) - 1 objects are scheduled
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type KILL
2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(89)) - Start TaskScheduler
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(148)) - Task Scheduler stopped
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_RUNNING to QUERY_KILL_WAIT
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (handle(244)) - ta_1414384947749_0000_000001_000000_00 is canceled from DefaultTaskScheduler
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(107)) - TaskScheduler schedulingThread stopped
2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.QueryUnitAttempt (transition(326)) - ta_1414384947749_0000_000001_000000_00 Received TA_KILLED Status from LocalTask
2014-10-26 21:42:27,893 ERROR: org.apache.tajo.master.querymaster.SubQuery (run(704)) - SubQuery (eb_1414384947749_0000_000001) ERROR:
org.apache.hadoop.service.ServiceStateException: org.apache.tajo.master.DefaultTaskScheduler cannot enter state STARTED from state STOPPED
at org.apache.hadoop.service.ServiceStateModel.checkStateTransition(ServiceStateModel.java:129)
at org.apache.hadoop.service.ServiceStateModel.enterState(ServiceStateModel.java:111)
at org.apache.hadoop.service.AbstractService.start(AbstractService.java:190)
at org.apache.tajo.master.DefaultTaskScheduler.start(DefaultTaskScheduler.java:112)
at org.apache.tajo.master.querymaster.SubQuery$InitAndRequestContainer$1.run(SubQuery.java:697)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1132)) - [eb_1414384947749_0000_000001] Task Completion Event (Total: 1, Success: 0, Killed: 1, Failed: 0)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1234)) - subQuery completed - eb_1414384947749_0000_000001 (total=1, success=0, killed=1)
2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.QueryMaster (cleanupExecutionBlock(185)) - cleanup executionBlocks:
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_KILL_WAIT to QUERY_ERROR
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
2014-10-26 21:42:27,894 ERROR: org.apache.tajo.master.querymaster.Query (handle(960)) - Can't handle this event at current state, type:EventType: QUERY_COMPLETED, oldState:QUERY_ERROR, nextState:QUERY_ERROR
org.apache.hadoop.yarn.state.InvalidStateTransitonException: Invalid event: QUERY_COMPLETED at QUERY_ERROR
at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:305)
at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
at org.apache.tajo.master.querymaster.Query.handle(Query.java:957)
at org.apache.tajo.master.querymaster.Query.handle(Query.java:63)
at org.apache.tajo.master.TajoAsyncDispatcher.dispatch(TajoAsyncDispatcher.java:137)
at org.apache.tajo.master.TajoAsyncDispatcher$1.run(TajoAsyncDispatcher.java:79)
at java.lang.Thread.run(Thread.java:744)
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type INTERNAL_ERROR
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 2.56 sec <<< FAILURE! - in org.apache.tajo.master.querymaster.TestKillQuery
testKillQueryFromInitState(org.apache.tajo.master.querymaster.TestKillQuery) Time elapsed: 2.56 sec <<< FAILURE!
java.lang.AssertionError: expected:<QUERY_KILLED> but was:<QUERY_ERROR>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at org.apache.tajo.master.querymaster.TestKillQuery.testKillQueryFromInitState(TestKillQuery.java:104)
Running org.apache.tajo.master.querymaster.TestQueryProgress
2014-10-26 21:42:30,183 INFO: org.apache.tajo.master.session.SessionManager (createSession(73)) - Session 3107d08d-ff44-48f2-9daa-ce368d786167 is created.
{noformat}
> TestKillQuery.testKillQueryFromInitState fails occasionally.
> ------------------------------------------------------------
>
> Key: TAJO-1138
> URL: https://issues.apache.org/jira/browse/TAJO-1138
> Project: Tajo
> Issue Type: Task
> Reporter: Hyunsik Choi
> Fix For: 0.9.1
>
>
> See the following logs:
> {noformat}
> 2014-10-26 21:42:27,889 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(731)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1414384947749_0000_000001
> 2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (listStatus(414)) - Total input paths to process : 1
> 2014-10-26 21:42:27,891 INFO: org.apache.tajo.storage.StorageManager (getSplits(643)) - Total # of splits: 1
> 2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.SubQuery (run(691)) - 1 objects are scheduled
> 2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type KILL
> 2014-10-26 21:42:27,891 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(89)) - Start TaskScheduler
> 2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(148)) - Task Scheduler stopped
> 2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_RUNNING to QUERY_KILL_WAIT
> 2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (handle(244)) - ta_1414384947749_0000_000001_000000_00 is canceled from DefaultTaskScheduler
> 2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(107)) - TaskScheduler schedulingThread stopped
> 2014-10-26 21:42:27,892 INFO: org.apache.tajo.master.querymaster.QueryUnitAttempt (transition(326)) - ta_1414384947749_0000_000001_000000_00 Received TA_KILLED Status from LocalTask
> 2014-10-26 21:42:27,893 ERROR: org.apache.tajo.master.querymaster.SubQuery (run(704)) - SubQuery (eb_1414384947749_0000_000001) ERROR:
> org.apache.hadoop.service.ServiceStateException: org.apache.tajo.master.DefaultTaskScheduler cannot enter state STARTED from state STOPPED
> at org.apache.hadoop.service.ServiceStateModel.checkStateTransition(ServiceStateModel.java:129)
> at org.apache.hadoop.service.ServiceStateModel.enterState(ServiceStateModel.java:111)
> at org.apache.hadoop.service.AbstractService.start(AbstractService.java:190)
> at org.apache.tajo.master.DefaultTaskScheduler.start(DefaultTaskScheduler.java:112)
> at org.apache.tajo.master.querymaster.SubQuery$InitAndRequestContainer$1.run(SubQuery.java:697)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> 2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1132)) - [eb_1414384947749_0000_000001] Task Completion Event (Total: 1, Success: 0, Killed: 1, Failed: 0)
> 2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1234)) - subQuery completed - eb_1414384947749_0000_000001 (total=1, success=0, killed=1)
> 2014-10-26 21:42:27,893 INFO: org.apache.tajo.master.querymaster.QueryMaster (cleanupExecutionBlock(185)) - cleanup executionBlocks:
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type SUBQUERY_COMPLETED
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(970)) - q_1414384947749_0000 Query Transitioned from QUERY_KILL_WAIT to QUERY_ERROR
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type QUERY_COMPLETED
> 2014-10-26 21:42:27,894 ERROR: org.apache.tajo.master.querymaster.Query (handle(960)) - Can't handle this event at current state, type:EventType: QUERY_COMPLETED, oldState:QUERY_ERROR, nextState:QUERY_ERROR
> org.apache.hadoop.yarn.state.InvalidStateTransitonException: Invalid event: QUERY_COMPLETED at QUERY_ERROR
> at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:305)
> at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
> at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
> at org.apache.tajo.master.querymaster.Query.handle(Query.java:957)
> at org.apache.tajo.master.querymaster.Query.handle(Query.java:63)
> at org.apache.tajo.master.TajoAsyncDispatcher.dispatch(TajoAsyncDispatcher.java:137)
> at org.apache.tajo.master.TajoAsyncDispatcher$1.run(TajoAsyncDispatcher.java:79)
> at java.lang.Thread.run(Thread.java:744)
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
> 2014-10-26 21:42:27,894 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
> 2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.Query (handle(952)) - Processing q_1414384947749_0000 of type INTERNAL_ERROR
> 2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(323)) - Query completion notified from q_1414384947749_0000
> 2014-10-26 21:42:27,895 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(334)) - Query final state: QUERY_ERROR
> Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 2.56 sec <<< FAILURE! - in org.apache.tajo.master.querymaster.TestKillQuery
> testKillQueryFromInitState(org.apache.tajo.master.querymaster.TestKillQuery) Time elapsed: 2.56 sec <<< FAILURE!
> java.lang.AssertionError: expected:<QUERY_KILLED> but was:<QUERY_ERROR>
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.failNotEquals(Assert.java:743)
> at org.junit.Assert.assertEquals(Assert.java:118)
> at org.junit.Assert.assertEquals(Assert.java:144)
> at org.apache.tajo.master.querymaster.TestKillQuery.testKillQueryFromInitState(TestKillQuery.java:104)
> Running org.apache.tajo.master.querymaster.TestQueryProgress
> 2014-10-26 21:42:30,183 INFO: org.apache.tajo.master.session.SessionManager (createSession(73)) - Session 3107d08d-ff44-48f2-9daa-ce368d786167 is created.
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)