You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tajo.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/03/14 04:18:02 UTC
Build failed in Jenkins: Tajo-master-nightly #300
See <https://builds.apache.org/job/Tajo-master-nightly/300/changes>
Changes:
[jinossy] TAJO-647: Work unbalance on disk scheduling of DefaultScheduler. (jinho)
[jinossy] TAJO-651: HcatalogStore should support (de)serialization of RCFile. (jinho)
[jinossy] TAJO-686: Integration test aborted. (jinho)
------------------------------------------
[...truncated 61780 lines...]
=======================================================
2014-03-14 03:17:51,659 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:start(101)) - AsyncDispatcher started:q_1394766883591_0196
2014-03-14 03:17:51,659 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type START
2014-03-14 03:17:51,659 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(755)) - Table's volume is approximately 1 MB
2014-03-14 03:17:51,660 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(762)) - Total memory of cluster is 1024 MB
2014-03-14 03:17:51,660 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(765)) - The determined number of aggregation partitions is 1
2014-03-14 03:17:51,661 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling
2014-03-14 03:17:51,664 INFO storage.AbstractStorageManager (AbstractStorageManager.java:listStatus(382)) - Total input paths to process : 1
2014-03-14 03:17:51,667 INFO storage.AbstractStorageManager (AbstractStorageManager.java:getSplits(607)) - Total # of splits: 1
2014-03-14 03:17:51,667 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled
2014-03-14 03:17:51,667 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler
2014-03-14 03:17:51,668 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-03-14 03:17:51,668 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000001 containers=1
2014-03-14 03:17:51,668 INFO querymaster.Query (Query.java:handle(654)) - q_1394766883591_0196 Query Transitioned from QUERY_NEW to QUERY_RUNNING
2014-03-14 03:17:51,668 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread
2014-03-14 03:17:51,670 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread
2014-03-14 03:17:51,671 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000001) has 1 containers!
2014-03-14 03:17:51,674 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo
2014-03-14 03:17:51,675 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir>
2014-03-14 03:17:51,675 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805
2014-03-14 03:17:51,675 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745
2014-03-14 03:17:51,676 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/1)
2014-03-14 03:17:51,677 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup
2014-03-14 03:17:51,679 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745
2014-03-14 03:17:51,680 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:allocateRackTask(701)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%, Rack host: 67.195.138.30
2014-03-14 03:17:51,683 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1
2014-03-14 03:17:51,684 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000001_000000_00
2014-03-14 03:17:51,686 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_PENDING
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(188)) - ==================================
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000001_000000_00 is initialized
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: true, Use HASH_SHUFFLE shuffle
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1)
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:0) :
2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/1/0_0>
2014-03-14 03:17:51,687 INFO worker.Task (Task.java:<init>(203)) - ==================================
2014-03-14 03:17:51,687 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_RUNNING
2014-03-14 03:17:51,687 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createBestAggregationPlan(955)) - The planner chooses [Hash Aggregation]
2014-03-14 03:17:51,688 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createInMemoryHashAggregation(898)) - The planner chooses [Hash Aggregation]
2014-03-14 03:17:51,697 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_SUCCEEDED
2014-03-14 03:17:51,697 INFO worker.Task (Task.java:run(447)) - Task Counter - total:450, succeeded: 446, killed: 1, failed: 3
2014-03-14 03:17:51,698 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745
2014-03-14 03:17:51,699 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000001] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0
2014-03-14 03:17:51,699 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000001 (total=1, success=1, killed=0)
2014-03-14 03:17:51,699 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped
2014-03-14 03:17:51,700 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped
2014-03-14 03:17:51,700 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745
2014-03-14 03:17:51,700 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000001
2014-03-14 03:17:51,700 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745
2014-03-14 03:17:51,700 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED
2014-03-14 03:17:51,700 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(769)) - ============>>>>> Unexpected Case! <<<<<================
2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(773)) - Table's volume is approximately 1 MB
2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(776)) - The determined number of partitions is 1
2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling
2014-03-14 03:17:51,701 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512
2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(805)) - Table's volume is approximately 1 MB
2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(808)) - The determined number of non-leaf tasks is 1
2014-03-14 03:17:51,702 INFO querymaster.Repartitioner (Repartitioner.java:scheduleHashShuffledFetches(482)) - ScheduleHashShuffledFetches - Max num=1, finalFetchURI=1
2014-03-14 03:17:51,702 INFO querymaster.Repartitioner (Repartitioner.java:scheduleHashShuffledFetches(492)) - DeterminedTaskNum : 1
2014-03-14 03:17:51,702 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled
2014-03-14 03:17:51,702 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler
2014-03-14 03:17:51,702 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-03-14 03:17:51,702 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000002 containers=1
2014-03-14 03:17:51,703 INFO querymaster.Query (Query.java:executeNextBlock(562)) - Scheduling SubQuery:eb_1394766883591_0196_000002
2014-03-14 03:17:51,703 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread
2014-03-14 03:17:51,704 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread
2014-03-14 03:17:51,704 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000002) has 1 containers!
2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo
2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir>
2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805
2014-03-14 03:17:51,707 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746
2014-03-14 03:17:51,707 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/2)
2014-03-14 03:17:51,708 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup
2014-03-14 03:17:51,708 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746
2014-03-14 03:17:51,710 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1
2014-03-14 03:17:51,711 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000002_000000_00
2014-03-14 03:17:51,712 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_PENDING
2014-03-14 03:17:51,712 INFO worker.Task (Task.java:<init>(188)) - ==================================
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000002_000000_00 is initialized
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: true, Use RANGE_SHUFFLE shuffle
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1)
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:1) :
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(196)) - Table Id: eb_1394766883591_0196_000001, url: http://67.195.138.30:36598/?qid=q_1394766883591_0196&sid=1&p=0&type=h&ta=0_0
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0>
2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(203)) - ==================================
2014-03-14 03:17:51,715 INFO worker.Task (Task.java:init(219)) - the directory is created <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/in/eb_1394766883591_0196_000002/0/0/eb_1394766883591_0196_000001>
2014-03-14 03:17:51,717 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_RUNNING
2014-03-14 03:17:51,718 INFO pullserver.TajoPullServerService (TajoPullServerService.java:channelOpen(346)) - Current number of shuffle connections (2)
2014-03-14 03:17:51,719 INFO worker.Fetcher (Fetcher.java:get(129)) - Fetch: http://67.195.138.30:36598/?qid=q_1394766883591_0196&sid=1&p=0&type=h&ta=0_0
2014-03-14 03:17:51,719 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(391)) - PullServer request param: shuffleType=h, sid=1, partId=0, taskIds=[0_0]
2014-03-14 03:17:51,719 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(397)) - PullServer baseDir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output>
2014-03-14 03:17:51,720 INFO worker.Task (Task.java:waitForFetch(356)) - ta_1394766883591_0196_000002_000000_00 All fetches are done!
2014-03-14 03:17:51,722 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createBestAggregationPlan(955)) - The planner chooses [Hash Aggregation]
2014-03-14 03:17:51,722 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createInMemoryHashAggregation(898)) - The planner chooses [Hash Aggregation]
2014-03-14 03:17:51,723 INFO physical.RangeShuffleFileWriteExec (RangeShuffleFileWriteExec.java:init(76)) - Output data directory: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output>
2014-03-14 03:17:51,748 INFO physical.ExternalSortExec (PhysicalExec.java:info(61)) - [ta_1394766883591_0196_000002_000000_00] Chunks creation time: 0 msec
2014-03-14 03:17:51,757 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_SUCCEEDED
2014-03-14 03:17:51,757 INFO worker.Task (Task.java:run(447)) - Task Counter - total:451, succeeded: 447, killed: 1, failed: 3
2014-03-14 03:17:51,757 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746
2014-03-14 03:17:51,758 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000002] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0
2014-03-14 03:17:51,758 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000002 (total=1, success=1, killed=0)
2014-03-14 03:17:51,758 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped
2014-03-14 03:17:51,758 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped
2014-03-14 03:17:51,759 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746
2014-03-14 03:17:51,759 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED
2014-03-14 03:17:51,759 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000002
2014-03-14 03:17:51,759 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746
2014-03-14 03:17:51,759 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling
2014-03-14 03:17:51,760 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(805)) - Table's volume is approximately 1 MB
2014-03-14 03:17:51,760 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(808)) - The determined number of non-leaf tasks is 1
2014-03-14 03:17:51,760 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512
2014-03-14 03:17:51,760 INFO querymaster.Repartitioner (Repartitioner.java:scheduleRangeShuffledFetches(352)) - Try to divide [(0=>N, 1=>F), (0=>R, 1=>O)) into 1 sub ranges (total units: 1)
2014-03-14 03:17:51,761 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled
2014-03-14 03:17:51,761 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler
2014-03-14 03:17:51,762 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-03-14 03:17:51,762 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000003 containers=1
2014-03-14 03:17:51,762 INFO querymaster.Query (Query.java:executeNextBlock(562)) - Scheduling SubQuery:eb_1394766883591_0196_000003
2014-03-14 03:17:51,762 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread
2014-03-14 03:17:51,763 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread
2014-03-14 03:17:51,763 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000003) has 1 containers!
2014-03-14 03:17:51,764 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo
2014-03-14 03:17:51,765 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir>
2014-03-14 03:17:51,765 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805
2014-03-14 03:17:51,765 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747
2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/3)
2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup
2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747
2014-03-14 03:17:51,768 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1
2014-03-14 03:17:51,768 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000003_000000_00
2014-03-14 03:17:51,769 INFO worker.Task (Task.java:<init>(183)) - Output File Path: hdfs://localhost:59092/tmp/tajo-jenkins/staging/q_1394766883591_0196/RESULT/part-03-000000
2014-03-14 03:17:51,769 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_PENDING
2014-03-14 03:17:51,769 INFO worker.Task (Task.java:<init>(188)) - ==================================
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000003_000000_00 is initialized
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: false
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1)
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:1) :
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(196)) - Table Id: eb_1394766883591_0196_000002, url: http://asf002.sp2.ygridcore.net:36598/?qid=q_1394766883591_0196&sid=2&ta=0_0&p=0&type=r&start=AAAAAU4AAAABRg%3D%3D&end=AAAAAVIAAAABTw%3D%3D&final=true
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/3/0_0>
2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(203)) - ==================================
2014-03-14 03:17:51,772 INFO worker.Task (Task.java:init(219)) - the directory is created <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/in/eb_1394766883591_0196_000003/0/0/eb_1394766883591_0196_000002>
2014-03-14 03:17:51,774 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_RUNNING
2014-03-14 03:17:51,775 INFO pullserver.TajoPullServerService (TajoPullServerService.java:channelOpen(346)) - Current number of shuffle connections (2)
2014-03-14 03:17:51,775 INFO worker.Fetcher (Fetcher.java:get(129)) - Fetch: http://asf002.sp2.ygridcore.net:36598/?qid=q_1394766883591_0196&sid=2&ta=0_0&p=0&type=r&start=AAAAAU4AAAABRg%3D%3D&end=AAAAAVIAAAABTw%3D%3D&final=true
2014-03-14 03:17:51,775 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(391)) - PullServer request param: shuffleType=r, sid=2, partId=0, taskIds=[0_0]
2014-03-14 03:17:51,776 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(397)) - PullServer baseDir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output>
2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(556)) - BSTIndex is loaded from disk ((0=>N, 1=>O), (0=>R, 1=>F)
2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(579)) - GET Request for <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output/output> (start=(0=>N, 1=>F), end=(0=>R, 1=>O), last=true)
2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(648)) - Retrieve File Chunk: (start=0, length=24) <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output/output>
2014-03-14 03:17:51,798 INFO worker.Task (Task.java:waitForFetch(356)) - ta_1394766883591_0196_000003_000000_00 All fetches are done!
2014-03-14 03:17:51,804 INFO physical.ExternalSortExec (PhysicalExec.java:info(61)) - [ta_1394766883591_0196_000003_000000_00] Total merge time: 0 msec
2014-03-14 03:17:51,810 INFO BlockStateChange (BlockManager.java:logAddStoredBlock(2237)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:47468 is added to blk_1073742100_1276{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[127.0.0.1:47468|RBW]]} size 12
2014-03-14 03:17:52,223 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_SUCCEEDED
2014-03-14 03:17:52,224 INFO worker.Task (Task.java:run(447)) - Task Counter - total:452, succeeded: 448, killed: 1, failed: 3
2014-03-14 03:17:52,224 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747
2014-03-14 03:17:52,225 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000003] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0
2014-03-14 03:17:52,225 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000003 (total=1, success=1, killed=0)
2014-03-14 03:17:52,225 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped
2014-03-14 03:17:52,225 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747
2014-03-14 03:17:52,225 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped
2014-03-14 03:17:52,225 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000003
2014-03-14 03:17:52,226 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747
2014-03-14 03:17:52,226 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED
2014-03-14 03:17:52,226 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type QUERY_COMPLETED
2014-03-14 03:17:52,226 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512
2014-03-14 03:17:52,227 INFO querymaster.Query (Query.java:handle(654)) - q_1394766883591_0196 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2014-03-14 03:17:52,227 INFO querymaster.QueryMasterTask (QueryMasterTask.java:handle(266)) - Query completion notified from q_1394766883591_0196
2014-03-14 03:17:52,227 INFO querymaster.QueryMasterTask (QueryMasterTask.java:handle(277)) - Query final state: QUERY_SUCCEEDED
2014-03-14 03:17:52,228 INFO querymaster.QueryMasterTask (QueryMasterTask.java:stop(172)) - Stopping QueryMasterTask:q_1394766883591_0196
2014-03-14 03:17:52,228 INFO querymaster.QueryJobManager (QueryJobManager.java:stopQuery(138)) - Stop QueryInProgress:q_1394766883591_0196
2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:heartbeat(257)) - Received QueryMaster heartbeat:q_1394766883591_0196state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf002.sp2.ygridcore.net
2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(108)) - =========================================================
2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(109)) - Stop query:q_1394766883591_0196
2014-03-14 03:17:52,229 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 0.0,512
2014-03-14 03:17:52,229 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:stopQueryMaster(534)) - Released QueryMaster (q_1394766883591_0196) resource:null
2014-03-14 03:17:52,229 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(117)) - q_1394766883591_0196 QueryMaster stopped
2014-03-14 03:17:52,230 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1394766883591_0196
2014-03-14 03:17:52,231 WARN master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(115)) - Interrupted Exception while stopping
2014-03-14 03:17:52,231 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:q_1394766883591_0196
2014-03-14 03:17:52,231 INFO querymaster.QueryMasterTask (QueryMasterTask.java:stop(200)) - Stopped QueryMasterTask:q_1394766883591_0196
2014-03-14 03:17:52,584 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:closeQuery(211)) - Stop Query:q_1394766883591_0196
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.522 sec
Running org.apache.tajo.jdbc.TestResultSet
2014-03-14 03:17:52,651 INFO BlockStateChange (BlockManager.java:logAddStoredBlock(2237)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:47468 is added to blk_1073742101_1277{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[127.0.0.1:47468|RBW]]} size 0
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.133 sec
2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(492)) - ============================================
2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(493)) - TajoWorker received SIGINT Signal
2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(494)) - ============================================
2014-03-14 03:17:52,734 INFO worker.WorkerHeartbeatService (WorkerHeartbeatService.java:run(251)) - Worker Resource Heartbeat Thread stopped.
2014-03-14 03:17:52,750 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:18806) shutdown
2014-03-14 03:17:52,751 INFO worker.TajoWorkerManagerService (TajoWorkerManagerService.java:stop(95)) - TajoWorkerManagerService stopped
2014-03-14 03:17:52,753 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:18805) shutdown
2014-03-14 03:17:52,753 INFO querymaster.QueryMasterManagerService (QueryMasterManagerService.java:stop(110)) - QueryMasterManagerService stopped
2014-03-14 03:17:52,753 INFO querymaster.QueryMaster (QueryMaster.java:run(423)) - QueryMaster heartbeat thread stopped
2014-03-14 03:17:52,756 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:querymaster_1394766884228
2014-03-14 03:17:52,756 INFO querymaster.QueryMaster (QueryMaster.java:stop(160)) - QueryMaster stop
2014-03-14 03:17:52,756 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:stop(107)) - TajoWorkerClientService stopping
2014-03-14 03:17:52,758 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:18804) shutdown
2014-03-14 03:17:52,758 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:stop(111)) - TajoWorkerClientService stopped
2014-03-14 03:17:52,758 INFO worker.TajoWorker (TajoWorker.java:stop(334)) - TajoWorker main thread exiting
Results :
Failed tests: testUnion7(org.apache.tajo.engine.query.TestUnionQuery): Result Verification expected:<[orderkey(..)
Tests run: 578, Failures: 1, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [16.746s]
[INFO] Tajo Project POM .................................. SUCCESS [5.060s]
[INFO] Tajo Common ....................................... SUCCESS [10.507s]
[INFO] Tajo Algebra ...................................... SUCCESS [3.497s]
[INFO] Tajo Rpc .......................................... SUCCESS [19.885s]
[INFO] Tajo Catalog Common ............................... SUCCESS [5.866s]
[INFO] Tajo Catalog Client ............................... SUCCESS [1.216s]
[INFO] Tajo Catalog Server ............................... SUCCESS [12.640s]
[INFO] Tajo Storage ...................................... SUCCESS [45.447s]
[INFO] Tajo Core PullServer .............................. SUCCESS [1.840s]
[INFO] Tajo Client ....................................... SUCCESS [3.932s]
[INFO] Tajo JDBC Driver .................................. SUCCESS [0.671s]
[INFO] Tajo Core Backend ................................. FAILURE [3:35.648s]
[INFO] Tajo Core ......................................... SKIPPED
[INFO] Tajo Catalog Drivers HCatalog ..................... SKIPPED
[INFO] Tajo Catalog Drivers .............................. SKIPPED
[INFO] Tajo Catalog ...................................... SKIPPED
[INFO] Tajo Distribution ................................. SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 5:43.922s
[INFO] Finished at: Fri Mar 14 03:17:53 UTC 2014
[INFO] Final Memory: 41M/359M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test (default-test) on project tajo-core-backend: There are test failures.
[ERROR]
[ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/surefire-reports> for the individual test results.
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR] mvn <goals> -rf :tajo-core-backend
Build step 'Execute shell' marked build as failure
Recording test results
Jenkins build is back to normal : Tajo-master-nightly #301
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Tajo-master-nightly/301/changes>