[
https://issues.apache.org/jira/browse/TAJO-869?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14053523#comment-14053523
]
Hyunsik Choi commented on TAJO-869:
-----------------------------------
Here is additional log.
{noformat}
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(start(101)) - AsyncDispatcher started:q_1404706448574_0608
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404706448574_0608 of type START
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.querymaster.SubQuery
(initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is
chosen for the task scheduling for eb_1404706448574_0608_000001
2014-07-07 13:22:32,297 INFO: org.apache.tajo.storage.AbstractStorageManager
(listStatus(386)) - Total input paths to process : 1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.storage.AbstractStorageManager
(getSplits(615)) - Total # of splits: 1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(647)) - 1 objects are scheduled
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.DefaultTaskScheduler
(start(87)) - Start TaskScheduler
2014-07-07 13:22:32,298 INFO: org.apache.tajo.worker.TajoResourceAllocator
(calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number
of Tasks=1, Number of Cluster Slots=1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.SubQuery
(allocateContainers(888)) - Request Container for eb_1404706448574_0608_000001
containers=1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.Query
(handle(705)) - q_1404706448574_0608 Query Transitioned from QUERY_NEW to
QUERY_RUNNING
2014-07-07 13:22:32,299 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(217)) - Start TajoWorkerAllocationThread
2014-07-07 13:22:32,299 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(336)) - Stop TajoWorkerAllocationThread
2014-07-07 13:22:32,299 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(997)) - SubQuery (eb_1404706448574_0608_000001) has 1 containers!
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) -
Tajo Root Dir: hdfs://localhost:62867/tajo
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) -
Worker Local Dir:
file:///Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/tajo-localdir
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) -
QueryMaster Address:192.168.0.118/192.168.0.118:27052
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunnerManager
(run(156)) - Start
TaskRunner:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:32,301 INFO: org.apache.tajo.worker.TaskRunner (init(191)) -
TaskRunner basedir is created (q_1404706448574_0608/output/1)
2014-07-07 13:22:32,301 INFO: org.apache.tajo.worker.TaskRunner (run(327)) -
TaskRunner startup
2014-07-07 13:22:32,302 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:32,303 INFO: org.apache.tajo.master.DefaultTaskScheduler
(allocateRackTask(718)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%,
Rack host: 192.168.0.118
2014-07-07 13:22:32,303 INFO: org.apache.tajo.worker.TaskRunner (run(385)) -
Accumulated Received Task: 1
2014-07-07 13:22:32,303 INFO: org.apache.tajo.worker.TaskRunner (run(394)) -
Initializing: ta_1404706448574_0608_000001_000000_00
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(184)) -
Output File Path:
hdfs://localhost:62867/tmp/tajo-hyunsik/staging/q_1404706448574_0608/RESULT/part-01-000000
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is
changed to TA_PENDING
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(189)) -
==================================
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(190)) - *
Subquery ta_1404706448574_0608_000001_000000_00 is initialized
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(191)) - *
InterQuery: false
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(194)) - *
Fragments (num: 1)
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(195)) - *
Fetches (total:0) :
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(199)) - *
Local task dir:
file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/tajo-localdir/q_1404706448574_0608/output/1/0_0
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(204)) -
==================================
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is
changed to TA_RUNNING
2014-07-07 13:22:33,199 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:62868 is added to
blk_1073742813_1989{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-90a75377-221a-4eef-9c85-2a7e3f066ff0:NORMAL|RBW]]}
size 0
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404706448574_0606_000001_000000_00 is
changed to TA_KILLED
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.Task (run(464)) - Worker's
task counter - total:1, succeeded: 0, killed: 2, failed: 0
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,201 WARN:
org.apache.tajo.master.querymaster.QueryMasterManagerService
(statusUpdate(162)) - ta_1404706448574_0606_000001_000000_00 Killed
2014-07-07 13:22:33,201 INFO:
org.apache.tajo.master.querymaster.QueryUnitAttempt (transition(343)) -
ta_1404706448574_0606_000001_000000_00 Received TA_KILLED Status from LocalTask
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunner (run(376)) -
Received ShouldDie
flag:eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) -
Stop TaskRunner: eb_1404706448574_0606_000001
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunnerManager
(stopTask(89)) - Stop
Task:eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,946 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received
QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_RUNNING,progress=0.0,
queryMaster=192.168.0.118
2014-07-07 13:22:35,947 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received
QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_RUNNING,progress=1.0,
queryMaster=192.168.0.118
2014-07-07 13:22:37,326 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:62868 is added to
blk_1073742814_1990{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-ce1eb997-27a6-4e8f-8bac-f59344d164d4:NORMAL|RBW]]}
size 0
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is
changed to TA_SUCCEEDED
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.Task (run(464)) - Worker's
task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1074)) - [eb_1404706448574_0608_000001] Task Completion Event
(Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1114)) - subQuery completed - eb_1404706448574_0608_000001
(total=1, success=1, killed=0)
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.DefaultTaskScheduler
(run(102)) - TaskScheduler schedulingThread stopped
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.DefaultTaskScheduler
(stop(143)) - Task Scheduler stopped
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunner (run(376)) -
Received ShouldDie
flag:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) -
Stop TaskRunner: eb_1404706448574_0608_000001
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunnerManager
(stopTask(89)) - Stop
Task:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404706448574_0608 of type SUBQUERY_COMPLETED
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404706448574_0608 of type QUERY_COMPLETED
2014-07-07 13:22:37,328 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager
(releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.Query
(handle(705)) - q_1404706448574_0608 Query Transitioned from QUERY_RUNNING to
QUERY_SUCCEEDED
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (handle(297)) - Query
completion notified from q_1404706448574_0608
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (handle(308)) - Query final
state: QUERY_SUCCEEDED
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (stop(187)) - Stopping
QueryMasterTask:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received
QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_SUCCEEDED,progress=1.0,
queryMaster=192.168.0.118
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryJobManager (stopQuery(203)) - Stop
QueryInProgress:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(116)) -
=========================================================
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(117)) - Stop
query:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager
(releaseWorkerResource(519)) - Release Resource: 0.0,512
2014-07-07 13:22:37,329 WARN: org.apache.tajo.master.TajoAsyncDispatcher
(stop(115)) - Interrupted Exception while stopping
2014-07-07 13:22:37,329 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager (stopQueryMaster(541)) -
Released QueryMaster (q_1404706448574_0608) resource.
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(stop(122)) - AsyncDispatcher stopped:q_1404706448574_0608
2014-07-07 13:22:37,330 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(125)) -
q_1404706448574_0608 QueryMaster stopped
2014-07-07 13:22:37,330 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (stop(217)) - Stopped
QueryMasterTask:q_1404706448574_0608
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.querymaster.QueryMaster
(cleanup(166)) - cleanup query resources : q_1404706448574_0608
2014-07-07 13:22:37,330 WARN: org.apache.tajo.master.TajoAsyncDispatcher
(stop(115)) - Interrupted Exception while stopping
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1404706448574_0608
2014-07-07 13:22:37,813 INFO: org.apache.tajo.master.session.SessionManager
(removeSession(80)) - Session 69b7b393-512f-4184-b938-9c730a9cca47 is removed.
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 11.12 sec <<<
FAILURE!
testTaskRunnerHistory(org.apache.tajo.worker.TestHistory) Time elapsed: 5.572
sec <<< FAILURE!
java.lang.AssertionError: expected:
org.apache.tajo.worker.TaskRunnerHistory<org.apache.tajo.worker.TaskRunnerHistory@f9402a96>
but was:
org.apache.tajo.worker.TaskRunnerHistory<org.apache.tajo.worker.TaskRunnerHistory@f9402a96>
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.worker.TestHistory.testTaskRunnerHistory(TestHistory.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
at
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
at
org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
at
org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)
Running org.apache.tajo.worker.TestRangeRetrieverHandler
2014-07-07 13:22:37,838 INFO: org.apache.tajo.TajoTestingCluster
(startCatalogCluster(241)) - Apache Derby repository is set to
jdbc:derby:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/774cc00b-f71c-4f49-90a0-0cca21e3544c/db
2014-07-07 13:22:37,838 INFO: org.apache.tajo.catalog.CatalogServer
(serviceInit(128)) - Catalog Store Class: org.apache.tajo.catalog.store.MemStore
2014-07-07 13:22:37,838 INFO: org.apache.tajo.rpc.RpcChannelFactory
(createServerChannelFactory(81)) - Create CatalogProtocol-87
ServerSocketChannelFactory. Worker:16
2014-07-07 13:22:37,841 INFO: org.apache.tajo.rpc.NettyServerBase (start(106))
- Rpc (CatalogProtocol) listens on /127.0.0.1:27132
2014-07-07 13:22:37,841 INFO: org.apache.tajo.catalog.CatalogServer
(start(188)) - Catalog Server startup (127.0.0.1:27132)
2014-07-07 13:22:37,842 INFO: org.apache.tajo.catalog.CatalogServer
(createTablespace(232)) - tablespace "default"
(file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273)
is created
2014-07-07 13:22:37,842 INFO: org.apache.tajo.catalog.CatalogServer
(createDatabase(357)) - database "default" is created
2014-07-07 13:22:37,893 INFO: org.apache.tajo.catalog.CatalogServer
(createTable(523)) - relation "default.employee" is added to the catalog
(127.0.0.1:27132)
2014-07-07 13:22:37,944 INFO:
org.apache.tajo.engine.planner.physical.RangeShuffleFileWriteExec (init(76)) -
Output data directory:
file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output
2014-07-07 13:22:37,987 INFO:
org.apache.tajo.engine.planner.physical.ExternalSortExec (info(61)) -
[ta_0000000000000_0073_000001_000076_42] Chunks creation time: 6 msec
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler
(<init>(73)) - BSTIndex is loaded from disk ((0=>9999, 1=>10004), (0=>0, 1=>5)
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler
(get(97)) - GET Request for
/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output/data/data
(start=(0=>9599, 1=>10004), end=(0=>9999, 1=>10004), last=true)
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler
(get(160)) - Retrieve File Chunk: (start=5200, length=-5200)
/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output/data/data
{noformat}
> Sometimes, the unit test of testTaskRunnerHistory is failed.
> ------------------------------------------------------------
>
> Key: TAJO-869
> URL: https://issues.apache.org/jira/browse/TAJO-869
> Project: Tajo
> Issue Type: Bug
> Reporter: Hyunsik Choi
> Priority: Critical
> Fix For: 0.9.0
>
>
> {noformat}
> Results :
> Failed tests: testTaskRunnerHistory(org.apache.tajo.worker.TestHistory):
> expected:
> org.apache.tajo.worker.TaskRunnerHistory<org.apache.tajo.worker.TaskRunnerHistory@63bec4ad>
> but was:
> org.apache.tajo.worker.TaskRunnerHistory<org.apache.tajo.worker.TaskRunnerHistory@63bec4ad>
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
