Uploaded image for project: 'Tajo'
  1. Tajo
  2. TAJO-869

Sometimes, the unit test of testTaskRunnerHistory is failed.

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 0.9.0
    • Fix Version/s: 0.9.0
    • Component/s: None
    • Labels:
      None

      Description

      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>
      

        Activity

        Hide
        hyunsik Hyunsik Choi added a comment -

        Here is additional log.

        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
        
        Show
        hyunsik Hyunsik Choi added a comment - Here is additional log. 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
        Hide
        jhkim Jinho Kim added a comment -

        Thanks. I'll investigate it soon.

        Show
        jhkim Jinho Kim added a comment - Thanks. I'll investigate it soon.
        Hide
        jhkim Jinho Kim added a comment -

        Hyunsik Choi

        I couldn't find this case in unit tests.
        Could you check your unit tests by this patch ?
        In addition, I removed ClosedChannelException.

        Thank you.

        Show
        jhkim Jinho Kim added a comment - Hyunsik Choi I couldn't find this case in unit tests. Could you check your unit tests by this patch ? In addition, I removed ClosedChannelException. Thank you.
        Hide
        hyunsik Hyunsik Choi added a comment -

        Actually, I also haven't found the exact cause of this failure.
        The HashMap, you replaced by SortedMap, seems to be a potential failure cause.
        Now, I tried to reproduce it, but I haven't.

        Anyway, your fix looks reasonable.
        Here is my +1 for the patch.

        If we see the failure later, we can dig into it more at that time.

        Show
        hyunsik Hyunsik Choi added a comment - Actually, I also haven't found the exact cause of this failure. The HashMap, you replaced by SortedMap, seems to be a potential failure cause. Now, I tried to reproduce it, but I haven't. Anyway, your fix looks reasonable. Here is my +1 for the patch. If we see the failure later, we can dig into it more at that time.
        Hide
        jhkim Jinho Kim added a comment -

        I agree, thank you for the review

        Show
        jhkim Jinho Kim added a comment - I agree, thank you for the review
        Hide
        jhkim Jinho Kim added a comment -

        committed it

        Show
        jhkim Jinho Kim added a comment - committed it
        Hide
        hudson Hudson added a comment -

        SUCCESS: Integrated in Tajo-master-build #293 (See https://builds.apache.org/job/Tajo-master-build/293/)
        TAJO-869: Sometimes, the unit test of testTaskRunnerHistory is failed. (jinho) (jinossy: rev 0a39818f5ee29be56b23060c978915fd7287fd0a)

        • CHANGES
        • tajo-core/src/main/java/org/apache/tajo/worker/Task.java
        • tajo-core/src/main/java/org/apache/tajo/worker/TaskRunnerHistory.java
        Show
        hudson Hudson added a comment - SUCCESS: Integrated in Tajo-master-build #293 (See https://builds.apache.org/job/Tajo-master-build/293/ ) TAJO-869 : Sometimes, the unit test of testTaskRunnerHistory is failed. (jinho) (jinossy: rev 0a39818f5ee29be56b23060c978915fd7287fd0a) CHANGES tajo-core/src/main/java/org/apache/tajo/worker/Task.java tajo-core/src/main/java/org/apache/tajo/worker/TaskRunnerHistory.java

          People

          • Assignee:
            jhkim Jinho Kim
            Reporter:
            hyunsik Hyunsik Choi
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development