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/07/01 04:17:21 UTC
Build failed in Jenkins: Tajo-master-nightly #388
See <https://builds.apache.org/job/Tajo-master-nightly/388/changes>
Changes:
[hyunsik] TAJO-894: Left outer join with partitioned large table and small table returns empty result. (Hyoungjun Kim via hyunsik)
------------------------------------------
[...truncated 177244 lines...]
=> in schema: {(16) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey (INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity (FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount (FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag (TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate (TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate (TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode (TEXT),default.lineitem.l_comment (TEXT)}
2014-07-01 02:16:38,727 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(477)) - =============================================
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.GlobalEngine (executeQueryInternal(285)) - Query is forwarded to :0
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.TajoAsyncDispatcher (start(101)) - AsyncDispatcher started:QueryInProgress:q_1404180576016_0512
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.querymaster.QueryInProgress (startQueryMaster(165)) - Initializing QueryInProgress for QueryID=q_1404180576016_0512
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.querymaster.QueryInProgress (connectQueryMaster(209)) - Connect to QueryMaster:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,729 INFO: org.apache.tajo.master.querymaster.QueryInProgress (submmitQueryToMaster(229)) - Call executeQuery to :asf001.sp2.ygridcore.net:16359,q_1404180576016_0512
2014-07-01 02:16:38,731 INFO: org.apache.tajo.master.querymaster.QueryMasterManagerService (executeQuery(236)) - Receive executeQuery request:q_1404180576016_0512
2014-07-01 02:16:38,732 INFO: org.apache.tajo.master.querymaster.QueryMaster (handle(374)) - Start QueryStartEventHandler:q_1404180576016_0512
2014-07-01 02:16:38,735 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (initStagingDir(380)) - The staging dir 'hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512' is created.
2014-07-01 02:16:38,772 INFO: org.apache.tajo.engine.planner.global.GlobalPlanner (build(116)) -
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
INSERT(2) INTO default.testcolumnpartitionedtablebyonecolumn
=> {(3) default.testcolumnpartitionedtablebyonecolumn.col1 (INT4),default.testcolumnpartitionedtablebyonecolumn.col2 (INT4),default.testcolumnpartitionedtablebyonecolumn.key (FLOAT8)}
PROJECTION(1)
=> Targets: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey (INT4), NULL as null_col, default.lineitem.l_quantity (FLOAT8)
=> out schema: {(4) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),null_col (NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(3) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
SCAN(0) on default.lineitem
=> target list: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey (INT4), default.lineitem.l_quantity (FLOAT8)
=> out schema: {(3) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(16) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey (INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity (FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount (FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag (TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate (TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate (TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode (TEXT),default.lineitem.l_comment (TEXT)}
2014-07-01 02:16:38,773 INFO: org.apache.tajo.engine.planner.global.GlobalPlanner (build(154)) -
-------------------------------------------------------------------------------
Execution Block Graph (TERMINAL - eb_1404180576016_0512_000003)
-------------------------------------------------------------------------------
|-eb_1404180576016_0512_000003
|-eb_1404180576016_0512_000002
|-eb_1404180576016_0512_000001
-------------------------------------------------------------------------------
=======================================================
Block Id: eb_1404180576016_0512_000001 [LEAF]
=======================================================
[Outgoing]
[q_1404180576016_0512] 1 => 2 (type=HASH_SHUFFLE, key=default.lineitem.l_quantity (FLOAT8), num=32)
PROJECTION(1)
=> Targets: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey (INT4), NULL as null_col, default.lineitem.l_quantity (FLOAT8)
=> out schema: {(4) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),null_col (NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(3) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
SCAN(0) on default.lineitem
=> target list: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey (INT4), default.lineitem.l_quantity (FLOAT8)
=> out schema: {(3) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(16) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey (INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity (FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount (FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag (TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate (TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate (TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode (TEXT),default.lineitem.l_comment (TEXT)}
=======================================================
Block Id: eb_1404180576016_0512_000002 [ROOT]
=======================================================
[Incoming]
[q_1404180576016_0512] 1 => 2 (type=HASH_SHUFFLE, key=default.lineitem.l_quantity (FLOAT8), num=32)
INSERT(2) INTO default.testcolumnpartitionedtablebyonecolumn
=> {(3) default.testcolumnpartitionedtablebyonecolumn.col1 (INT4),default.testcolumnpartitionedtablebyonecolumn.col2 (INT4),default.testcolumnpartitionedtablebyonecolumn.key (FLOAT8)}
SCAN(5) on eb_1404180576016_0512_000001
=> out schema: {(4) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),null_col (NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(4) default.lineitem.l_orderkey (INT4),default.lineitem.l_partkey (INT4),null_col (NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=======================================================
Block Id: eb_1404180576016_0512_000003 [TERMINAL]
=======================================================
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.TajoAsyncDispatcher (start(101)) - AsyncDispatcher started:q_1404180576016_0512
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404180576016_0512 of type START
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery (calculateShuffleOutputNum(801)) - ============>>>>> Unexpected Case! <<<<<================
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery (calculateShuffleOutputNum(805)) - eb_1404180576016_0512_000001, Table's volume is approximately 1 MB
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery (calculateShuffleOutputNum(808)) - eb_1404180576016_0512_000001, The determined number of partitions is 1
2014-07-01 02:16:38,775 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1404180576016_0512_000001
2014-07-01 02:16:38,776 INFO: org.apache.tajo.storage.AbstractStorageManager (listStatus(386)) - Total input paths to process : 1
2014-07-01 02:16:38,777 INFO: org.apache.tajo.storage.AbstractStorageManager (getSplits(615)) - Total # of splits: 1
2014-07-01 02:16:38,777 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(647)) - 1 objects are scheduled
2014-07-01 02:16:38,777 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(87)) - Start TaskScheduler
2014-07-01 02:16:38,778 INFO: org.apache.tajo.worker.TajoResourceAllocator (calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-07-01 02:16:38,778 INFO: org.apache.tajo.master.querymaster.SubQuery (allocateContainers(888)) - Request Container for eb_1404180576016_0512_000001 containers=1
2014-07-01 02:16:38,778 INFO: org.apache.tajo.master.querymaster.Query (handle(705)) - q_1404180576016_0512 Query Transitioned from QUERY_NEW to QUERY_RUNNING
2014-07-01 02:16:38,778 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(217)) - Start TajoWorkerAllocationThread
2014-07-01 02:16:38,779 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(336)) - Stop TajoWorkerAllocationThread
2014-07-01 02:16:38,779 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(997)) - SubQuery (eb_1404180576016_0512_000001) has 1 containers!
2014-07-01 02:16:38,780 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) - Tajo Root Dir: hdfs://localhost:59625/tajo
2014-07-01 02:16:38,780 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir>
2014-07-01 02:16:38,781 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) - QueryMaster Address:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,782 INFO: org.apache.tajo.worker.TaskRunnerManager (run(156)) - Start TaskRunner:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,782 INFO: org.apache.tajo.worker.TaskRunner (init(191)) - TaskRunner basedir is created (q_1404180576016_0512/output/1)
2014-07-01 02:16:38,783 INFO: org.apache.tajo.worker.TaskRunner (run(327)) - TaskRunner startup
2014-07-01 02:16:38,783 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,784 INFO: org.apache.tajo.master.DefaultTaskScheduler (allocateRackTask(707)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%, Rack host: 67.195.138.31
2014-07-01 02:16:38,785 INFO: org.apache.tajo.worker.TaskRunner (run(385)) - Accumulated Received Task: 1
2014-07-01 02:16:38,785 INFO: org.apache.tajo.worker.TaskRunner (run(394)) - Initializing: ta_1404180576016_0512_000001_000000_00
2014-07-01 02:16:38,786 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is changed to TA_PENDING
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(188)) - ==================================
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(189)) - * Subquery ta_1404180576016_0512_000001_000000_00 is initialized
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(190)) - * InterQuery: true, Use HASH_SHUFFLE shuffle
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(193)) - * Fragments (num: 1)
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(194)) - * Fetches (total:0) :
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output/1/0_0>
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(203)) - ==================================
2014-07-01 02:16:38,788 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is changed to TA_RUNNING
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is changed to TA_SUCCEEDED
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.Task (run(452)) - Worker's task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,792 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1074)) - [eb_1404180576016_0512_000001] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1114)) - subQuery completed - eb_1404180576016_0512_000001 (total=1, success=1, killed=0)
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(102)) - TaskScheduler schedulingThread stopped
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(143)) - Task Scheduler stopped
2014-07-01 02:16:38,793 INFO: org.apache.tajo.worker.TaskRunner (run(376)) - Received ShouldDie flag:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404180576016_0512 of type SUBQUERY_COMPLETED
2014-07-01 02:16:38,793 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) - Stop TaskRunner: eb_1404180576016_0512_000001
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1404180576016_0512_000002
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.SubQuery (getNonLeafTaskNum(837)) - Table's volume is approximately 1 MB
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.SubQuery (getNonLeafTaskNum(840)) - The determined number of non-leaf tasks is 1
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-01 02:16:38,794 INFO: org.apache.tajo.worker.TaskRunnerManager (stopTask(89)) - Stop Task:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.Repartitioner (scheduleHashShuffledFetches(575)) - eb_1404180576016_0512_000002, ScheduleHashShuffledFetches - Max num=1, finalFetchURI=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.Repartitioner (scheduleHashShuffledFetches(591)) - eb_1404180576016_0512_000002, DeterminedTaskNum : 1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(647)) - 1 objects are scheduled
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(87)) - Start TaskScheduler
2014-07-01 02:16:38,795 INFO: org.apache.tajo.worker.TajoResourceAllocator (calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.SubQuery (allocateContainers(888)) - Request Container for eb_1404180576016_0512_000002 containers=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.Query (executeNextBlock(609)) - Scheduling SubQuery:eb_1404180576016_0512_000002
2014-07-01 02:16:38,795 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(217)) - Start TajoWorkerAllocationThread
2014-07-01 02:16:38,796 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(336)) - Stop TajoWorkerAllocationThread
2014-07-01 02:16:38,796 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(997)) - SubQuery (eb_1404180576016_0512_000002) has 1 containers!
2014-07-01 02:16:38,797 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) - Tajo Root Dir: hdfs://localhost:59625/tajo
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir>
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) - QueryMaster Address:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunnerManager (run(156)) - Start TaskRunner:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (init(191)) - TaskRunner basedir is created (q_1404180576016_0512/output/2)
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (run(327)) - TaskRunner startup
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,801 INFO: org.apache.tajo.worker.TaskRunner (run(385)) - Accumulated Received Task: 1
2014-07-01 02:16:38,801 INFO: org.apache.tajo.worker.TaskRunner (run(394)) - Initializing: ta_1404180576016_0512_000002_000000_00
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(183)) - Output File Path: hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/part-02-000000
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is changed to TA_PENDING
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(188)) - ==================================
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(189)) - * Subquery ta_1404180576016_0512_000002_000000_00 is initialized
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(190)) - * InterQuery: false
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(193)) - * Fragments (num: 1)
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(194)) - * Fetches (total:1) :
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(196)) - Table Id: eb_1404180576016_0512_000001, Simple URIs: [http://67.195.138.31:46064/?qid=q_1404180576016_0512&sid=1&p=0&type=h]
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output/2/0_0>
2014-07-01 02:16:38,803 INFO: org.apache.tajo.worker.Task (<init>(203)) - ==================================
2014-07-01 02:16:38,804 INFO: org.apache.tajo.worker.Task (init(219)) - the directory is created <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/in/eb_1404180576016_0512_000002/0/0/eb_1404180576016_0512_000001>
2014-07-01 02:16:38,806 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is changed to TA_RUNNING
2014-07-01 02:16:38,806 INFO: org.apache.tajo.pullserver.TajoPullServerService (channelOpen(349)) - Current number of shuffle connections (2)
2014-07-01 02:16:38,806 INFO: org.apache.tajo.worker.Fetcher (get(126)) - Fetch: http://67.195.138.31:46064/?qid=q_1404180576016_0512&sid=1&p=0&type=h&ta=0_0
2014-07-01 02:16:38,807 INFO: org.apache.tajo.pullserver.TajoPullServerService (messageReceived(394)) - PullServer request param: shuffleType=h, sid=1, partId=0, taskIds=[0_0]
2014-07-01 02:16:38,807 INFO: org.apache.tajo.pullserver.TajoPullServerService (messageReceived(400)) - PullServer baseDir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output>
2014-07-01 02:16:38,808 INFO: org.apache.tajo.worker.Task (waitForFetch(360)) - ta_1404180576016_0512_000002_000000_00 All fetches are done!
2014-07-01 02:16:38,809 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createSortBasedColumnPartitionStorePlan(826)) - The planner chooses [Sort-based Column Partitioned Store] algorithm
2014-07-01 02:16:38,810 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(61)) - [ta_1404180576016_0512_000002_000000_00] Chunks creation time: 0 msec
2014-07-01 02:16:38,812 INFO: org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec (getAppender(74)) - Add subpartition path directory :hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=17.0
2014-07-01 02:16:38,819 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to blk_1073742653_1829{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]} size 0
2014-07-01 02:16:38,824 INFO: org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec (getAppender(74)) - Add subpartition path directory :hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=36.0
2014-07-01 02:16:38,833 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to blk_1073742654_1830{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-9e0aefb3-e358-4388-98b1-81e7288c67ee:NORMAL|RBW]]} size 0
2014-07-01 02:16:38,836 INFO: org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec (getAppender(74)) - Add subpartition path directory :hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=38.0
2014-07-01 02:16:38,844 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to blk_1073742655_1831{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]} size 0
2014-07-01 02:16:38,847 INFO: org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec (getAppender(74)) - Add subpartition path directory :hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=45.0
2014-07-01 02:16:38,855 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to blk_1073742656_1832{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-9e0aefb3-e358-4388-98b1-81e7288c67ee:NORMAL|RBW]]} size 0
2014-07-01 02:16:38,859 INFO: org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec (getAppender(74)) - Add subpartition path directory :hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=49.0
2014-07-01 02:16:38,866 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to blk_1073742657_1833{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]} size 0
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is changed to TA_SUCCEEDED
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.Task (run(452)) - Worker's task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1074)) - [eb_1404180576016_0512_000002] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1114)) - subQuery completed - eb_1404180576016_0512_000002 (total=1, success=1, killed=0)
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(143)) - Task Scheduler stopped
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(102)) - TaskScheduler schedulingThread stopped
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404180576016_0512 of type SUBQUERY_COMPLETED
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404180576016_0512 of type QUERY_COMPLETED
2014-07-01 02:16:38,868 INFO: org.apache.tajo.worker.TaskRunner (run(376)) - Received ShouldDie flag:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,869 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-01 02:16:38,869 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) - Stop TaskRunner: eb_1404180576016_0512_000002
2014-07-01 02:16:38,869 INFO: org.apache.tajo.worker.TaskRunnerManager (stopTask(89)) - Stop Task:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,873 INFO: org.apache.tajo.catalog.CatalogServer (dropTable(554)) - relation "default.testcolumnpartitionedtablebyonecolumn" is deleted from the catalog (127.0.0.1:16355)
2014-07-01 02:16:38,874 INFO: org.apache.tajo.catalog.CatalogServer (createTable(523)) - relation "default.testcolumnpartitionedtablebyonecolumn" is added to the catalog (127.0.0.1:16355)
2014-07-01 02:16:38,874 INFO: org.apache.tajo.master.querymaster.Query (handle(705)) - q_1404180576016_0512 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2014-07-01 02:16:38,874 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(297)) - Query completion notified from q_1404180576016_0512
2014-07-01 02:16:38,874 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(308)) - Query final state: QUERY_SUCCEEDED
2014-07-01 02:16:38,874 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (stop(187)) - Stopping QueryMasterTask:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received QueryMaster heartbeat:q_1404180576016_0512,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf001.sp2.ygridcore.net
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.querymaster.QueryJobManager (stopQuery(203)) - Stop QueryInProgress:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(116)) - =========================================================
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(117)) - Stop query:q_1404180576016_0512
2014-07-01 02:16:38,875 WARN: org.apache.tajo.master.TajoAsyncDispatcher (stop(115)) - Interrupted Exception while stopping
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.TajoAsyncDispatcher (stop(122)) - AsyncDispatcher stopped:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (releaseWorkerResource(519)) - Release Resource: 0.0,512
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (stopQueryMaster(541)) - Released QueryMaster (q_1404180576016_0512) resource.
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(125)) - q_1404180576016_0512 QueryMaster stopped
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (stop(217)) - Stopped QueryMasterTask:q_1404180576016_0512
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.querymaster.QueryMaster (cleanup(166)) - cleanup query resources : q_1404180576016_0512
2014-07-01 02:16:38,876 WARN: org.apache.tajo.master.TajoAsyncDispatcher (stop(115)) - Interrupted Exception while stopping
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.TajoAsyncDispatcher (stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1404180576016_0512
Killed
Results :
Tests run: 878, Failures: 0, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [55.731s]
[INFO] Tajo Project POM .................................. SUCCESS [3.038s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [8.134s]
[INFO] Tajo Common ....................................... SUCCESS [1:16.656s]
[INFO] Tajo Algebra ...................................... SUCCESS [5.211s]
[INFO] Tajo Catalog Common ............................... SUCCESS [6.835s]
[INFO] Tajo Rpc .......................................... SUCCESS [23.148s]
[INFO] Tajo Catalog Client ............................... SUCCESS [1.130s]
[INFO] Tajo Catalog Server ............................... SUCCESS [6.977s]
[INFO] Tajo Storage ...................................... SUCCESS [56.128s]
[INFO] Tajo Core PullServer .............................. SUCCESS [1.390s]
[INFO] Tajo Client ....................................... SUCCESS [4.296s]
[INFO] Tajo JDBC Driver .................................. SUCCESS [2.001s]
[INFO] Tajo Catalog Drivers HCatalog ..................... SUCCESS [13.821s]
[INFO] Tajo Core ......................................... FAILURE [7:31.612s]
[INFO] Tajo Catalog Drivers .............................. SKIPPED
[INFO] Tajo Catalog ...................................... SKIPPED
[INFO] Tajo Distribution ................................. SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 11:57.721s
[INFO] Finished at: Tue Jul 01 02:16:39 UTC 2014
[INFO] Final Memory: 50M/406M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test (default-test) on project tajo-core: Execution default-test of goal org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test failed: The forked VM terminated without saying properly goodbye. VM crash or System.exit called ? -> [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/PluginExecutionException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR] mvn <goals> -rf :tajo-core
Build step 'Execute shell' marked build as failure
Recording test results
Jenkins build is back to normal : Tajo-master-nightly #389
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Tajo-master-nightly/389/changes>