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 2015/09/16 00:42:49 UTC
Build failed in Jenkins: Tajo-master-jdk8-nightly #150
See <https://builds.apache.org/job/Tajo-master-jdk8-nightly/150/changes>
Changes:
[hyunsik] TAJO-1848: ShutdownHook in TajoMaster can throw NPE if serviceInit() is failed.
------------------------------------------
[...truncated 742313 lines...]
=> in schema:{(1) default.lineitem.l_orderkey (INT4)}
SCAN(0) on default.lineitem
=> target list: default.lineitem.l_orderkey (INT4)
=> out schema: {(1) default.lineitem.l_orderkey (INT4)}
=> 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_1442355649336_2118_000002 [ROOT]
=======================================================
[Incoming]
[q_1442355649336_2118] 1 => 2 (type=HASH_SHUFFLE, key=default.lineitem.l_orderkey (INT4), num=32)
GROUP_BY(1)(l_orderkey)
=> target list: default.lineitem.l_orderkey (INT4)
=> out schema:{(1) default.lineitem.l_orderkey (INT4)}
=> in schema:{(1) default.lineitem.l_orderkey (INT4)}
SCAN(6) on eb_1442355649336_2118_000001
=> out schema: {(1) default.lineitem.l_orderkey (INT4)}
=> in schema: {(1) default.lineitem.l_orderkey (INT4)}
=======================================================
Block Id: eb_1442355649336_2118_000003 [TERMINAL]
=======================================================
2015-09-15 22:41:54,844 INFO: org.apache.tajo.querymaster.Query (<init>(235)) -
=======================================================
The order of execution:
1: eb_1442355649336_2118_000001
2: eb_1442355649336_2118_000002
3: eb_1442355649336_2118_000003
=======================================================
2015-09-15 22:41:54,845 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58648 is added to blk_1073748644_7820{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-ad47703f-0c82-43f2-96c5-f1b0db2ed27a:NORMAL:127.0.0.1:58648|FINALIZED]]} size 0
2015-09-15 22:41:54,845 INFO: org.apache.tajo.querymaster.Query (handle(855)) - Processing q_1442355649336_2118 of type START
2015-09-15 22:41:54,845 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (first(84)) - Initial executable blocks [eb_1442355649336_2118_000001]
2015-09-15 22:41:54,845 INFO: org.apache.tajo.querymaster.Query (handle(873)) - q_1442355649336_2118 Query Transitioned from QUERY_NEW to QUERY_RUNNING
2015-09-15 22:41:54,845 INFO: org.apache.tajo.querymaster.Stage (calculateShuffleOutputNum(1014)) - eb_1442355649336_2118_000001, Table's volume is approximately 1 MB
2015-09-15 22:41:54,845 INFO: org.apache.tajo.querymaster.Stage (calculateShuffleOutputNum(1018)) - eb_1442355649336_2118_000001, The determined number of aggregation partitions is 1
2015-09-15 22:41:54,846 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(897)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1442355649336_2118_000001
2015-09-15 22:41:54,846 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:50439/tmp/tajo-jenkins/staging/history/20150915/query-detail/q_1442355649336_2117/eb_1442355649336_2117_000001.hist
2015-09-15 22:41:54,847 INFO: org.apache.tajo.storage.FileTablespace (listStatus(368)) - Total input paths to process : 1
2015-09-15 22:41:54,848 INFO: org.apache.tajo.storage.FileTablespace (getSplits(569)) - Total # of splits: 1
2015-09-15 22:41:54,848 INFO: org.apache.tajo.querymaster.Stage (run(849)) - 1 objects are scheduled
2015-09-15 22:41:54,848 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(131)) - Start TaskScheduler
2015-09-15 22:41:54,848 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58648 is added to blk_1073748645_7821{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-5ff51e7d-5739-432c-91f0-ce4a664dfcb3:NORMAL:127.0.0.1:58648|FINALIZED]]} size 0
2015-09-15 22:41:54,853 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (increaseConcurrency(521)) - Assigned host : 127.0.0.1, Unknown Volume : -1, Concurrency : 1
2015-09-15 22:41:54,853 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(112)) - QueryMaster Address:asf901.gq1.ygridcore.net:45225
2015-09-15 22:41:54,854 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (assignToLeafTasks(915)) - Assigned Local/Rack/Total: (0/1/1), Attempted Cancel/Assign/Total: (0/1/1), Locality: 0.00%, Rack host: asf901.gq1.ygridcore.net
2015-09-15 22:41:54,853 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:50439/tmp/tajo-jenkins/staging/history/20150915/query-detail/q_1442355649336_2117/eb_1442355649336_2117_000004.hist
2015-09-15 22:41:54,855 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:50439/tajo
2015-09-15 22:41:54,855 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir>
2015-09-15 22:41:54,856 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58648 is added to blk_1073748646_7822{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-ad47703f-0c82-43f2-96c5-f1b0db2ed27a:NORMAL:127.0.0.1:58648|RBW]]} size 0
2015-09-15 22:41:54,856 INFO: org.apache.tajo.worker.TaskManager (handle(182)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:2, vCores:2)
2015-09-15 22:41:54,857 INFO: org.apache.tajo.worker.TaskImpl (<init>(114)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/output/1)>
2015-09-15 22:41:54,857 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000001_000000_00 is changed to TA_PENDING
2015-09-15 22:41:54,857 INFO: org.apache.tajo.worker.TaskImpl (init(195)) - Initializing: ta_1442355649336_2118_000001_000000_00
2015-09-15 22:41:54,857 INFO: org.apache.tajo.worker.TaskImpl (initPlan(150)) - ==================================
2015-09-15 22:41:54,857 INFO: org.apache.tajo.worker.TaskImpl (initPlan(151)) - * Stage ta_1442355649336_2118_000001_000000_00 is initialized
2015-09-15 22:41:54,858 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - * InterQuery: true, Use HASH_SHUFFLE shuffle, Fragments (num: 1), Fetches (total:0) :
2015-09-15 22:41:54,858 INFO: org.apache.tajo.worker.TaskImpl (initPlan(162)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/output/1/0_0>
2015-09-15 22:41:54,858 INFO: org.apache.tajo.worker.TaskImpl (initPlan(167)) - ==================================
2015-09-15 22:41:54,858 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000001_000000_00 is changed to TA_RUNNING
2015-09-15 22:41:54,858 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createBestAggregationPlan(1030)) - Aggregation:estimatedSize=604, threshold=67108864
2015-09-15 22:41:54,858 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createBestAggregationPlan(1032)) - The planner chooses [Hash Aggregation]
2015-09-15 22:41:54,858 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createInMemoryHashAggregation(974)) - The planner chooses [Hash Aggregation]
2015-09-15 22:41:54,862 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000001_000000_00 is changed to TA_SUCCEEDED
2015-09-15 22:41:54,862 INFO: org.apache.tajo.worker.TaskImpl (run(460)) - ta_1442355649336_2118_000001_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0
2015-09-15 22:41:54,862 INFO: org.apache.tajo.querymaster.Stage (transition(1345)) - Stage - eb_1442355649336_2118_000001 finalize HASH_SHUFFLE (total=1, success=1, killed=0)
2015-09-15 22:41:54,862 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(160)) - Task Scheduler stopped
2015-09-15 22:41:54,863 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(123)) - TaskScheduler schedulingThread stopped
2015-09-15 22:41:54,863 INFO: org.apache.tajo.querymaster.Stage (transition(1356)) - eb_1442355649336_2118_000001, wait for HASH_SHUFFLE reports. expected Tasks:1
2015-09-15 22:41:54,863 INFO: org.apache.tajo.storage.HashShuffleAppenderManager (close(155)) - Close HashShuffleAppender:eb_1442355649336_2118_000001, intermediates=1
2015-09-15 22:41:54,864 INFO: org.apache.tajo.querymaster.Stage (finalizeShuffleReport(1302)) - eb_1442355649336_2118_000001, Finalized HASH_SHUFFLE reports: 1
2015-09-15 22:41:54,864 INFO: org.apache.tajo.querymaster.Stage (transition(1403)) - Stage completed - eb_1442355649336_2118_000001 (total=1, success=1, killed=0)
2015-09-15 22:41:54,864 INFO: org.apache.tajo.querymaster.Query (handle(855)) - Processing q_1442355649336_2118 of type STAGE_COMPLETED
2015-09-15 22:41:54,864 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(161)) - Stopped execution block:eb_1442355649336_2118_000001
2015-09-15 22:41:54,864 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1442355649336_2118_000002
2015-09-15 22:41:54,864 INFO: org.apache.tajo.querymaster.Query (executeNextBlock(757)) - Scheduling Stage:eb_1442355649336_2118_000002
2015-09-15 22:41:54,864 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(897)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1442355649336_2118_000002
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1091)) - eb_1442355649336_2118_000002, Table's volume is approximately 1 MB
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1096)) - eb_1442355649336_2118_000002, The determined number of non-leaf tasks is 1
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleHashShuffledFetches(865)) - eb_1442355649336_2118_000002, ScheduleHashShuffledFetches - Max num=1, finalFetchURI=1
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleHashShuffledFetches(885)) - eb_1442355649336_2118_000002, DeterminedTaskNum : 1
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.Stage (run(849)) - 1 objects are scheduled
2015-09-15 22:41:54,865 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(131)) - Start TaskScheduler
2015-09-15 22:41:54,866 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(112)) - QueryMaster Address:asf901.gq1.ygridcore.net:45225
2015-09-15 22:41:54,868 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:50439/tajo
2015-09-15 22:41:54,868 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir>
2015-09-15 22:41:54,868 INFO: org.apache.tajo.worker.TaskManager (handle(182)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:3, vCores:2)
2015-09-15 22:41:54,868 INFO: org.apache.tajo.worker.TaskImpl (<init>(114)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/output/2)>
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000002_000000_00 is changed to TA_PENDING
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (init(195)) - Initializing: ta_1442355649336_2118_000002_000000_00
2015-09-15 22:41:54,869 INFO: org.apache.tajo.storage.FileTablespace (getAppenderFilePath(294)) - Output File Path: hdfs://localhost:50439/tmp/tajo-jenkins/staging/q_1442355649336_2118/RESULT/part-02-000000-000
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(145)) - Output File Path: hdfs://localhost:50439/tmp/tajo-jenkins/staging/q_1442355649336_2118/RESULT/part-02-000000-000
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(150)) - ==================================
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(151)) - * Stage ta_1442355649336_2118_000002_000000_00 is initialized
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - * InterQuery: false, Fragments (num: 1), Fetches (total:1) :
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(162)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/output/2/0_0>
2015-09-15 22:41:54,869 INFO: org.apache.tajo.worker.TaskImpl (initPlan(167)) - ==================================
2015-09-15 22:41:54,870 INFO: org.apache.tajo.worker.TaskImpl (init(214)) - the directory is created <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/in/eb_1442355649336_2118_000002/0/0/eb_1442355649336_2118_000001>
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(692)) - Try to get local file chunk at local host
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (getLocalStoredFileChunk(734)) - getLocalStoredFileChunk starts
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (getLocalStoredFileChunk(769)) - PullServer request param: shuffleType=h, sid=1, partId=0, taskIds=null
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(720)) - Create a new Fetcher with storeChunk: (start=0, length=24, fromRemote=false, ebId=eb_1442355649336_2118_000001) <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/5d018b2f-9141-4c1d-aaed-23d9d9e0ef5e/tajo-localdir/q_1442355649336_2118/output/1/hash-shuffle/0/0>
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000002_000000_00 is changed to TA_RUNNING
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.Fetcher (get(128)) - Get pseudo fetch from local host
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (run(616)) - Add a new FileChunk to local chunk list
2015-09-15 22:41:54,871 INFO: org.apache.tajo.worker.TaskImpl (waitForFetch(362)) - ta_1442355649336_2118_000002_000000_00 All fetches are done!
2015-09-15 22:41:54,872 INFO: org.apache.tajo.worker.TaskImpl (localizeFetchedData(572)) - One local chunk is added to listTablets
2015-09-15 22:41:54,872 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createBestAggregationPlan(1030)) - Aggregation:estimatedSize=24, threshold=67108864
2015-09-15 22:41:54,872 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createBestAggregationPlan(1032)) - The planner chooses [Hash Aggregation]
2015-09-15 22:41:54,872 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createInMemoryHashAggregation(974)) - The planner chooses [Hash Aggregation]
2015-09-15 22:41:54,876 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58648 is added to blk_1073748647_7823{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-5ff51e7d-5739-432c-91f0-ce4a664dfcb3:NORMAL:127.0.0.1:58648|RBW]]} size 0
2015-09-15 22:41:54,877 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442355649336_2118_000002_000000_00 is changed to TA_SUCCEEDED
2015-09-15 22:41:54,877 INFO: org.apache.tajo.worker.TaskImpl (run(460)) - ta_1442355649336_2118_000002_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0
2015-09-15 22:41:54,877 INFO: org.apache.tajo.querymaster.Stage (transition(1345)) - Stage - eb_1442355649336_2118_000002 finalize NONE_SHUFFLE (total=1, success=1, killed=0)
2015-09-15 22:41:54,878 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(160)) - Task Scheduler stopped
2015-09-15 22:41:54,878 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(123)) - TaskScheduler schedulingThread stopped
2015-09-15 22:41:54,878 INFO: org.apache.tajo.querymaster.Stage (transition(1403)) - Stage completed - eb_1442355649336_2118_000002 (total=1, success=1, killed=0)
2015-09-15 22:41:54,878 INFO: org.apache.tajo.querymaster.Query (handle(855)) - Processing q_1442355649336_2118 of type STAGE_COMPLETED
2015-09-15 22:41:54,878 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1442355649336_2118_000003
2015-09-15 22:41:54,879 INFO: org.apache.tajo.querymaster.Query (transition(802)) - Complete Stage[eb_1442355649336_2118_000002], State: SUCCEEDED, 2/2.
2015-09-15 22:41:54,879 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(161)) - Stopped execution block:eb_1442355649336_2118_000002
2015-09-15 22:41:54,879 INFO: org.apache.tajo.querymaster.Query (handle(855)) - Processing q_1442355649336_2118 of type QUERY_COMPLETED
2015-09-15 22:41:54,880 INFO: org.apache.tajo.querymaster.Query (handle(873)) - q_1442355649336_2118 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2015-09-15 22:41:54,880 INFO: org.apache.tajo.querymaster.QueryMasterTask (handle(292)) - Query completion notified from q_1442355649336_2118 final state: QUERY_SUCCEEDED
2015-09-15 22:41:54,880 INFO: org.apache.tajo.master.QueryInProgress (heartbeat(253)) - Received QueryMaster heartbeat:q_1442355649336_2118,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf901.gq1.ygridcore.net
2015-09-15 22:41:54,880 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(169)) - Stopping QueryMasterTask:q_1442355649336_2118
2015-09-15 22:41:54,880 INFO: org.apache.tajo.master.QueryManager (stopQuery(279)) - Stop QueryInProgress:q_1442355649336_2118
2015-09-15 22:41:54,881 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(118)) - =========================================================
2015-09-15 22:41:54,881 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(119)) - Stop query:q_1442355649336_2118
2015-09-15 22:41:54,881 INFO: org.apache.tajo.querymaster.QueryMasterTask (cleanupQuery(469)) - Cleanup resources of all workers. Query: q_1442355649336_2118, workers: 1
2015-09-15 22:41:54,882 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 2eea7be8-a8e7-424e-936f-c83d85a81ad0 is removed.
2015-09-15 22:41:54,882 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(185)) - Stopped QueryMasterTask:q_1442355649336_2118
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.34 sec - in org.apache.tajo.querymaster.TestQueryProgress
Running org.apache.tajo.TestQueryIdFactory
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 sec - in org.apache.tajo.TestQueryIdFactory
Running org.apache.tajo.resource.TestResources
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 sec - in org.apache.tajo.resource.TestResources
2015-09-15 22:41:54,887 INFO: org.mortbay.log (info(67)) - Shutdown hook executing
2015-09-15 22:41:54,888 INFO: org.mortbay.log (info(67)) - Shutdown hook complete
2015-09-15 22:41:54,900 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 3267bbab-dbae-45c2-9ecb-f4d921ef91da is removed.
2015-09-15 22:41:54,902 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session c13d0d96-ee69-4eb4-b71a-52d5f4fdf0a4 is removed.
2015-09-15 22:41:54,904 INFO: org.apache.tajo.worker.TajoWorker (run(570)) - ============================================
2015-09-15 22:41:54,906 INFO: org.apache.tajo.worker.TajoWorker (run(571)) - TajoWorker received SIGINT Signal
2015-09-15 22:41:54,906 INFO: org.apache.tajo.worker.TajoWorker (run(572)) - ============================================
2015-09-15 22:41:54,908 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_asf901.gq1.ygridcore.net_45223 stopped.
2015-09-15 22:41:54,910 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped
2015-09-15 22:41:54,949 INFO: org.apache.tajo.worker.NodeStatusUpdater (serviceStop(111)) - NodeStatusUpdater stopped.
2015-09-15 22:41:54,951 INFO: org.apache.tajo.worker.NodeStatusUpdater (run(262)) - Heartbeat Thread stopped.
2015-09-15 22:41:54,952 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:45225) shutdown
2015-09-15 22:41:54,954 INFO: org.apache.tajo.querymaster.QueryMasterManagerService (serviceStop(106)) - QueryMasterManagerService stopped
2015-09-15 22:41:54,954 INFO: org.apache.tajo.querymaster.QueryMaster (run(425)) - QueryMaster heartbeat thread stopped
2015-09-15 22:41:54,956 INFO: org.apache.tajo.querymaster.QueryMaster (serviceStop(161)) - QueryMaster stopped
2015-09-15 22:41:54,956 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(98)) - TajoWorkerClientService stopping
2015-09-15 22:41:54,957 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:45224) shutdown
2015-09-15 22:41:54,957 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(102)) - TajoWorkerClientService stopped
2015-09-15 22:41:54,958 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:45223) shutdown
2015-09-15 22:41:54,958 INFO: org.apache.tajo.worker.TajoWorkerManagerService (serviceStop(93)) - TajoWorkerManagerService stopped
2015-09-15 22:41:54,959 INFO: org.apache.tajo.worker.TajoWorker (serviceStop(380)) - TajoWorker main thread exiting
2015-09-15 22:41:54,959 INFO: org.apache.tajo.rpc.RpcClientManager (close(184)) - Closing RPC client manager
Results :
Failed tests:
TestDDLBuilder.testBuildDDLForExternalTable:64 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]') PARTITION BY COLU...> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]') PARTITION BY COLU...>
TestDDLBuilder.testBuildDDLForBaseTable:103 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]');> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]');>
TestDDLBuilder.testBuildDDLQuotedTableName:90 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]') PARTITION BY COLU...> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]') PARTITION BY COLU...>
TestUnionQuery.testUnionAndFilter:698->QueryTestCaseBase.runSimpleTests:604 Result Verification for: 1 th test expected:<...-------------------
[4,2866.83
1,711.56
5,794.47
3,7498.12
2,121.65]
> but was:<...-------------------
[1,711.56
4,2866.83
5,794.47
2,121.65
3,7498.12]
>
Tests run: 1639, Failures: 4, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [ 1.561 s]
[INFO] Tajo Project POM .................................. SUCCESS [ 1.274 s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [ 2.566 s]
[INFO] Tajo Common ....................................... SUCCESS [ 30.288 s]
[INFO] Tajo Algebra ...................................... SUCCESS [ 2.216 s]
[INFO] Tajo Catalog Common ............................... SUCCESS [ 4.766 s]
[INFO] Tajo Plan ......................................... SUCCESS [ 6.198 s]
[INFO] Tajo Rpc Common ................................... SUCCESS [ 1.219 s]
[INFO] Tajo Protocol Buffer Rpc .......................... SUCCESS [ 51.910 s]
[INFO] Tajo Catalog Client ............................... SUCCESS [ 1.416 s]
[INFO] Tajo Catalog Server ............................... SUCCESS [ 8.972 s]
[INFO] Tajo Storage Common ............................... SUCCESS [ 2.499 s]
[INFO] Tajo HDFS Storage ................................. SUCCESS [ 47.663 s]
[INFO] Tajo PullServer ................................... SUCCESS [ 0.905 s]
[INFO] Tajo Client ....................................... SUCCESS [ 2.786 s]
[INFO] Tajo CLI tools .................................... SUCCESS [ 1.721 s]
[INFO] Tajo SQL Parser ................................... SUCCESS [ 3.554 s]
[INFO] ASM (thirdparty) .................................. SUCCESS [ 1.847 s]
[INFO] Tajo RESTful Container ............................ SUCCESS [ 3.779 s]
[INFO] Tajo Metrics ...................................... SUCCESS [ 1.387 s]
[INFO] Tajo Core ......................................... SUCCESS [ 5.712 s]
[INFO] Tajo RPC .......................................... SUCCESS [ 0.931 s]
[INFO] Tajo Catalog Drivers Hive ......................... SUCCESS [ 9.739 s]
[INFO] Tajo Catalog Drivers .............................. SUCCESS [ 0.063 s]
[INFO] Tajo Catalog ...................................... SUCCESS [ 0.967 s]
[INFO] Tajo Client Example ............................... SUCCESS [ 1.031 s]
[INFO] Tajo HBase Storage ................................ SUCCESS [ 3.379 s]
[INFO] Tajo Cluster Tests ................................ SUCCESS [ 1.969 s]
[INFO] Tajo JDBC Driver .................................. SUCCESS [01:01 min]
[INFO] Tajo Storage ...................................... SUCCESS [ 0.946 s]
[INFO] Tajo Distribution ................................. SUCCESS [ 5.308 s]
[INFO] Tajo Core Tests ................................... FAILURE [21:45 min]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 26:16 min
[INFO] Finished at: 2015-09-15T22:42:25+00:00
[INFO] Final Memory: 149M/2116M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.17:test (default-test) on project tajo-core-tests: There are test failures.
[ERROR]
[ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/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-tests
Build step 'Execute shell' marked build as failure
Archiving artifacts
Sending artifact delta relative to Tajo-master-jdk8-nightly #82
Archived 1 artifacts
Archive block size is 32768
Received 0 blocks and 59210463 bytes
Compression is 0.0%
Took 20 sec
Recording test results
Build failed in Jenkins: Tajo-master-jdk8-nightly #151
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Tajo-master-jdk8-nightly/151/changes>
Changes:
[jihoonson] TAJO-1813: Allow external catalog store for unit testing.
[jhkim] TAJO-1851: Can not release a different rack task.
[blrunner] TAJO-1824: Remove partition_keys table from information_schema.
------------------------------------------
[...truncated 743784 lines...]
2015-09-16 05:20:39,893 INFO: org.apache.tajo.worker.TaskImpl (localizeFetchedData(572)) - One local chunk is added to listTablets
2015-09-16 05:20:39,893 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createFullOuterHashJoinPlan(622)) - Full Outer Join (6) chooses [Hash Join]
2015-09-16 05:20:39,893 INFO: org.apache.tajo.engine.planner.physical.RangeShuffleFileWriteExec (init(80)) - Output data directory: <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/3/0_0/output>
2015-09-16 05:20:39,918 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(70)) - [ta_1442379484131_2118_000003_000000_00] Chunks creation time: 1 msec
2015-09-16 05:20:39,923 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442379484131_2118_000003_000000_00 is changed to TA_SUCCEEDED
2015-09-16 05:20:39,923 INFO: org.apache.tajo.worker.TaskImpl (run(460)) - ta_1442379484131_2118_000003_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.Stage (transition(1345)) - Stage - eb_1442379484131_2118_000003 finalize RANGE_SHUFFLE (total=1, success=1, killed=0)
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(160)) - Task Scheduler stopped
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(123)) - TaskScheduler schedulingThread stopped
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.Stage (transition(1403)) - Stage completed - eb_1442379484131_2118_000003 (total=1, success=1, killed=0)
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.Query (handle(851)) - Processing q_1442379484131_2118 of type STAGE_COMPLETED
2015-09-16 05:20:39,924 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1442379484131_2118_000004
2015-09-16 05:20:39,924 INFO: org.apache.tajo.querymaster.Query (executeNextBlock(753)) - Scheduling Stage:eb_1442379484131_2118_000004
2015-09-16 05:20:39,925 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(897)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1442379484131_2118_000004
2015-09-16 05:20:39,925 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(161)) - Stopped execution block:eb_1442379484131_2118_000003
2015-09-16 05:20:39,925 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1091)) - eb_1442379484131_2118_000004, Table's volume is approximately 1 MB
2015-09-16 05:20:39,925 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1096)) - eb_1442379484131_2118_000004, The determined number of non-leaf tasks is 1
2015-09-16 05:20:39,925 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleRangeShuffledFetches(670)) - eb_1442379484131_2118_000004, Try to divide [(1,1), (5,3)) into 1 sub ranges (total units: 1)
2015-09-16 05:20:39,926 INFO: org.apache.tajo.engine.utils.TupleUtil (setMaxRangeIfNull(104)) - Set null into range: default.orders.o_orderkey, current tuple is (5,NULL)
2015-09-16 05:20:39,926 INFO: org.apache.tajo.querymaster.Stage (run(849)) - 1 objects are scheduled
2015-09-16 05:20:39,926 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(131)) - Start TaskScheduler
2015-09-16 05:20:39,928 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(112)) - QueryMaster Address:asf906.gq1.ygridcore.net:34064
2015-09-16 05:20:39,929 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:58233/tajo
2015-09-16 05:20:39,929 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir>
2015-09-16 05:20:39,930 INFO: org.apache.tajo.worker.TaskManager (handle(182)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:3, vCores:2)
2015-09-16 05:20:39,930 INFO: org.apache.tajo.worker.TaskImpl (<init>(114)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/4)>
2015-09-16 05:20:39,930 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442379484131_2118_000004_000000_00 is changed to TA_PENDING
2015-09-16 05:20:39,930 INFO: org.apache.tajo.worker.TaskImpl (init(195)) - Initializing: ta_1442379484131_2118_000004_000000_00
2015-09-16 05:20:39,930 INFO: org.apache.tajo.storage.FileTablespace (getAppenderFilePath(294)) - Output File Path: hdfs://localhost:58233/tmp/tajo-jenkins/staging/q_1442379484131_2118/RESULT/part-04-000000-000
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(145)) - Output File Path: hdfs://localhost:58233/tmp/tajo-jenkins/staging/q_1442379484131_2118/RESULT/part-04-000000-000
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(150)) - ==================================
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(151)) - * Stage ta_1442379484131_2118_000004_000000_00 is initialized
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - * InterQuery: false, Fragments (num: 1), Fetches (total:1) :
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(162)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/4/0_0>
2015-09-16 05:20:39,931 INFO: org.apache.tajo.worker.TaskImpl (initPlan(167)) - ==================================
2015-09-16 05:20:39,932 INFO: org.apache.tajo.worker.TaskImpl (init(214)) - the directory is created <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/in/eb_1442379484131_2118_000004/0/0/eb_1442379484131_2118_000003>
2015-09-16 05:20:39,932 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(692)) - Try to get local file chunk at local host
2015-09-16 05:20:39,932 INFO: org.apache.tajo.worker.TaskImpl (getLocalStoredFileChunk(734)) - getLocalStoredFileChunk starts
2015-09-16 05:20:39,932 INFO: org.apache.tajo.worker.TaskImpl (getLocalStoredFileChunk(769)) - PullServer request param: shuffleType=r, sid=3, partId=0, taskIds=[0_0]
2015-09-16 05:20:39,950 INFO: org.apache.tajo.pullserver.TajoPullServerService (getFileChunks(686)) - BSTIndex is loaded from disk ((1,1), (5,NULL)
2015-09-16 05:20:39,950 INFO: org.apache.tajo.pullserver.TajoPullServerService (getFileChunks(710)) - GET Request for <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/3/0_0/output/output> (start=(1,1), end=(5,NULL), last=true)
2015-09-16 05:20:39,950 INFO: org.apache.tajo.pullserver.TajoPullServerService (getFileChunks(779)) - Retrieve File Chunk: (start=0, length=49, fromRemote=false, ebId=null) <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/3/0_0/output/output>
2015-09-16 05:20:39,950 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(720)) - Create a new Fetcher with storeChunk: (start=0, length=49, fromRemote=false, ebId=eb_1442379484131_2118_000003) <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/3/0_0/output/output>
2015-09-16 05:20:39,950 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442379484131_2118_000004_000000_00 is changed to TA_RUNNING
2015-09-16 05:20:39,950 INFO: org.apache.tajo.worker.Fetcher (get(128)) - Get pseudo fetch from local host
2015-09-16 05:20:39,950 INFO: org.apache.tajo.worker.TaskImpl (run(616)) - Add a new FileChunk to local chunk list
2015-09-16 05:20:39,950 INFO: org.apache.tajo.worker.TaskImpl (waitForFetch(362)) - ta_1442379484131_2118_000004_000000_00 All fetches are done!
2015-09-16 05:20:39,951 INFO: org.apache.tajo.worker.TaskImpl (localizeFetchedData(572)) - One local chunk is added to listTablets
2015-09-16 05:20:39,952 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(70)) - [ta_1442379484131_2118_000004_000000_00] Total merge time: 0 msec
2015-09-16 05:20:39,953 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (close(791)) - Delete file: "fragment": {"id": "eb_1442379484131_2118_000003", "path": <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/target/test-data/0a455fb2-3ba2-4d27-8e9d-e4b4391fec15/tajo-localdir/q_1442379484131_2118/output/3/0_0/output/output",> "start": 0,"length": 49}
2015-09-16 05:20:39,957 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748642_7818{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-add98999-0f7f-4183-9dfe-4b383e9c7eea:NORMAL:127.0.0.1:51573|FINALIZED]]} size 0
2015-09-16 05:20:39,958 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(142)) - Query status of ta_1442379484131_2118_000004_000000_00 is changed to TA_SUCCEEDED
2015-09-16 05:20:39,958 INFO: org.apache.tajo.worker.TaskImpl (run(460)) - ta_1442379484131_2118_000004_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0
2015-09-16 05:20:39,959 INFO: org.apache.tajo.querymaster.Stage (transition(1345)) - Stage - eb_1442379484131_2118_000004 finalize NONE_SHUFFLE (total=1, success=1, killed=0)
2015-09-16 05:20:39,959 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(160)) - Task Scheduler stopped
2015-09-16 05:20:39,960 INFO: org.apache.tajo.querymaster.Stage (transition(1403)) - Stage completed - eb_1442379484131_2118_000004 (total=1, success=1, killed=0)
2015-09-16 05:20:39,960 INFO: org.apache.tajo.querymaster.Query (handle(851)) - Processing q_1442379484131_2118 of type STAGE_COMPLETED
2015-09-16 05:20:39,960 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1442379484131_2118_000005
2015-09-16 05:20:39,960 INFO: org.apache.tajo.querymaster.Query (transition(798)) - Complete Stage[eb_1442379484131_2118_000004], State: SUCCEEDED, 4/4.
2015-09-16 05:20:39,960 INFO: org.apache.tajo.querymaster.Query (handle(851)) - Processing q_1442379484131_2118 of type QUERY_COMPLETED
2015-09-16 05:20:39,961 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(161)) - Stopped execution block:eb_1442379484131_2118_000004
2015-09-16 05:20:39,961 INFO: org.apache.tajo.querymaster.Query (handle(869)) - q_1442379484131_2118 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2015-09-16 05:20:39,961 INFO: org.apache.tajo.querymaster.QueryMasterTask (handle(292)) - Query completion notified from q_1442379484131_2118 final state: QUERY_SUCCEEDED
2015-09-16 05:20:39,962 INFO: org.apache.tajo.master.QueryInProgress (heartbeat(253)) - Received QueryMaster heartbeat:q_1442379484131_2118,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf906.gq1.ygridcore.net
2015-09-16 05:20:39,962 INFO: org.apache.tajo.master.QueryManager (stopQuery(279)) - Stop QueryInProgress:q_1442379484131_2118
2015-09-16 05:20:39,962 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(118)) - =========================================================
2015-09-16 05:20:39,962 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(119)) - Stop query:q_1442379484131_2118
2015-09-16 05:20:39,962 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(169)) - Stopping QueryMasterTask:q_1442379484131_2118
2015-09-16 05:20:39,963 INFO: org.apache.tajo.querymaster.QueryMasterTask (cleanupQuery(469)) - Cleanup resources of all workers. Query: q_1442379484131_2118, workers: 1
2015-09-16 05:20:39,964 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(185)) - Stopped QueryMasterTask:q_1442379484131_2118
2015-09-16 05:20:39,965 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(123)) - TaskScheduler schedulingThread stopped
2015-09-16 05:20:40,030 INFO: org.apache.tajo.storage.FileTablespace (listStatus(368)) - Total input paths to process : 1
2015-09-16 05:20:40,031 INFO: org.apache.tajo.storage.FileTablespace (getSplits(569)) - Total # of splits: 1
2015-09-16 05:20:40,034 INFO: BlockStateChange (addToInvalidates(1106)) - BLOCK* addToInvalidates: blk_1073748642_7818 127.0.0.1:51573
2015-09-16 05:20:40,034 INFO: org.apache.tajo.master.exec.NonForwardQueryResultFileScanner (close(174)) - "Sent result to client for 32c8fa5c-7690-4bcc-9c18-b277ffd78d52, queryId: q_1442379484131_2118 rows: 5
2015-09-16 05:20:40,035 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(365)) - Saving query summary: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2117/query.hist
2015-09-16 05:20:40,039 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 32c8fa5c-7690-4bcc-9c18-b277ffd78d52 is removed.
2015-09-16 05:20:40,043 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748643_7819{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-9df86e4a-4ead-414b-b7b7-293c7931f087:NORMAL:127.0.0.1:51573|FINALIZED]]} size 0
2015-09-16 05:20:40,044 INFO: org.apache.tajo.session.SessionManager (createSession(80)) - Session 11cb3bc5-1ce3-491f-b466-25666abc7503 is created.
2015-09-16 05:20:40,045 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2117/eb_1442379484131_2117_000002.hist
2015-09-16 05:20:40,046 INFO: org.apache.tajo.master.GlobalEngine (executeQuery(176)) - Query: create table "TEST_DESC_TABLE" (col1 int4, col2 int4)
2015-09-16 05:20:40,046 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(280)) - Non Optimized Query:
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
2015-09-16 05:20:40,046 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(282)) - =============================================
2015-09-16 05:20:40,047 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(283)) - Optimized Query:
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
2015-09-16 05:20:40,047 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(284)) - =============================================
2015-09-16 05:20:40,049 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748644_7820{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-add98999-0f7f-4183-9dfe-4b383e9c7eea:NORMAL:127.0.0.1:51573|FINALIZED]]} size 0
2015-09-16 05:20:40,049 INFO: org.apache.tajo.catalog.CatalogServer (createTable(675)) - relation "default.TEST_DESC_TABLE" is added to the catalog (127.0.0.1:34058)
2015-09-16 05:20:40,049 INFO: org.apache.tajo.master.exec.DDLExecutor (create(111)) - relation 'default.TEST_DESC_TABLE' created.
2015-09-16 05:20:40,051 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2117/eb_1442379484131_2117_000001.hist
2015-09-16 05:20:40,054 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748645_7821{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-9df86e4a-4ead-414b-b7b7-293c7931f087:NORMAL:127.0.0.1:51573|RBW]]} size 0
2015-09-16 05:20:40,055 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 11cb3bc5-1ce3-491f-b466-25666abc7503 is removed.
2015-09-16 05:20:40,056 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(365)) - Saving query summary: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2118/query.hist
Tests run: 22, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.514 sec - in org.apache.tajo.cli.tsql.TestTajoCli
2015-09-16 05:20:40,061 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748646_7822{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-add98999-0f7f-4183-9dfe-4b383e9c7eea:NORMAL:127.0.0.1:51573|RBW]]} size 0
2015-09-16 05:20:40,063 INFO: org.mortbay.log (info(67)) - Shutdown hook executing
2015-09-16 05:20:40,065 INFO: org.mortbay.log (info(67)) - Shutdown hook complete
Sep 16, 2015 5:08:33 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:34 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:53 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:53 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:53 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:53 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:53 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
Sep 16, 2015 5:08:57 AM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers
2015-09-16 05:20:40,066 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2118/eb_1442379484131_2118_000004.hist
2015-09-16 05:20:40,072 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748647_7823{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-9df86e4a-4ead-414b-b7b7-293c7931f087:NORMAL:127.0.0.1:51573|RBW]]} size 0
2015-09-16 05:20:40,073 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 2d9e0a77-98f1-4280-8d85-c998da7a32e5 is removed.
2015-09-16 05:20:40,075 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2118/eb_1442379484131_2118_000003.hist
2015-09-16 05:20:40,076 INFO: org.apache.tajo.session.SessionManager (removeSession(86)) - Session 4879e383-49f6-4c73-b220-39e8c3d016ed is removed.
2015-09-16 05:20:40,078 INFO: org.apache.tajo.worker.TajoWorker (run(570)) - ============================================
2015-09-16 05:20:40,078 INFO: org.apache.tajo.worker.TajoWorker (run(571)) - TajoWorker received SIGINT Signal
2015-09-16 05:20:40,078 INFO: org.apache.tajo.worker.TajoWorker (run(572)) - ============================================
2015-09-16 05:20:40,081 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped
2015-09-16 05:20:40,084 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748648_7824{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-add98999-0f7f-4183-9dfe-4b383e9c7eea:NORMAL:127.0.0.1:51573|FINALIZED]]} size 0
2015-09-16 05:20:40,085 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2118/eb_1442379484131_2118_000002.hist
2015-09-16 05:20:40,085 WARN: org.apache.hadoop.hdfs.DFSClient (run(824)) - DFSOutputStream ResponseProcessor exception for block BP-344275308-67.195.81.150-1442379479879:blk_1073748648_7824
java.util.NoSuchElementException
at java.util.LinkedList.getFirst(LinkedList.java:244)
at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:781)
2015-09-16 05:20:40,092 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748649_7825{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-9df86e4a-4ead-414b-b7b7-293c7931f087:NORMAL:127.0.0.1:51573|FINALIZED]]} size 0
2015-09-16 05:20:40,094 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:58233/tmp/tajo-jenkins/staging/history/20150916/query-detail/q_1442379484131_2118/eb_1442379484131_2118_000001.hist
2015-09-16 05:20:40,098 ERROR: org.apache.hadoop.hdfs.DFSClient (closeAllFilesBeingWritten(954)) - Failed to close inode 29893
java.io.IOException: All datanodes DatanodeInfoWithStorage[127.0.0.1:51573,DS-9df86e4a-4ead-414b-b7b7-293c7931f087,DISK] are bad. Aborting...
at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.setupPipelineForAppendOrRecovery(DFSOutputStream.java:1084)
at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.processDatanodeError(DFSOutputStream.java:876)
at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:402)
2015-09-16 05:20:40,101 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:51573 is added to blk_1073748650_7826{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-add98999-0f7f-4183-9dfe-4b383e9c7eea:NORMAL:127.0.0.1:51573|RBW]]} size 0
2015-09-16 05:20:40,102 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_asf906.gq1.ygridcore.net_34062 stopped.
2015-09-16 05:20:40,127 INFO: org.apache.tajo.worker.NodeStatusUpdater (serviceStop(111)) - NodeStatusUpdater stopped.
2015-09-16 05:20:40,127 INFO: org.apache.tajo.worker.NodeStatusUpdater (run(262)) - Heartbeat Thread stopped.
2015-09-16 05:20:40,129 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:34064) shutdown
2015-09-16 05:20:40,130 INFO: org.apache.tajo.querymaster.QueryMasterManagerService (serviceStop(106)) - QueryMasterManagerService stopped
2015-09-16 05:20:40,130 INFO: org.apache.tajo.querymaster.QueryMaster (run(425)) - QueryMaster heartbeat thread stopped
2015-09-16 05:20:40,131 INFO: org.apache.tajo.querymaster.QueryMaster (serviceStop(161)) - QueryMaster stopped
2015-09-16 05:20:40,131 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(98)) - TajoWorkerClientService stopping
2015-09-16 05:20:40,132 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:34063) shutdown
2015-09-16 05:20:40,132 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(102)) - TajoWorkerClientService stopped
2015-09-16 05:20:40,132 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:34062) shutdown
2015-09-16 05:20:40,132 INFO: org.apache.tajo.worker.TajoWorkerManagerService (serviceStop(93)) - TajoWorkerManagerService stopped
2015-09-16 05:20:40,132 INFO: org.apache.tajo.worker.TajoWorker (serviceStop(380)) - TajoWorker main thread exiting
2015-09-16 05:20:40,132 INFO: org.apache.tajo.rpc.RpcClientManager (close(184)) - Closing RPC client manager
2015-09-16 05:20:40,331 INFO: BlockStateChange (invalidateWorkForOneNode(3488)) - BLOCK* BlockManager: ask 127.0.0.1:51573 to delete [blk_1073748640_7816, blk_1073748641_7817, blk_1073748642_7818, blk_1073748639_7815]
Results :
Failed tests:
TestUnionQuery.testUnionAndFilter:698->QueryTestCaseBase.runSimpleTests:604 Result Verification for: 1 th test expected:<...-------------------
[4,2866.83
1,711.56
5,794.47
3,7498.12
2,121.65]
> but was:<...-------------------
[1,711.56
4,2866.83
5,794.47
2,121.65
3,7498.12]
>
TestDDLBuilder.testBuildDDLForExternalTable:64 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]') PARTITION BY COLU...> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]') PARTITION BY COLU...>
TestDDLBuilder.testBuildDDLForBaseTable:103 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]');> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]');>
TestDDLBuilder.testBuildDDLQuotedTableName:90 expected:<...) USING TEXT WITH ('[compression.codec'='org.apache.hadoop.io.compress.GzipCodec', 'text.delimiter'='|]') PARTITION BY COLU...> but was:<...) USING TEXT WITH ('[text.delimiter'='|', 'compression.codec'='org.apache.hadoop.io.compress.GzipCodec]') PARTITION BY COLU...>
Tests run: 1639, Failures: 4, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [ 2.209 s]
[INFO] Tajo Project POM .................................. SUCCESS [ 1.977 s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [ 3.925 s]
[INFO] Tajo Common ....................................... SUCCESS [ 31.581 s]
[INFO] Tajo Algebra ...................................... SUCCESS [ 2.552 s]
[INFO] Tajo Catalog Common ............................... SUCCESS [ 5.000 s]
[INFO] Tajo Plan ......................................... SUCCESS [ 6.858 s]
[INFO] Tajo Rpc Common ................................... SUCCESS [ 1.354 s]
[INFO] Tajo Protocol Buffer Rpc .......................... SUCCESS [ 49.793 s]
[INFO] Tajo Catalog Client ............................... SUCCESS [ 1.475 s]
[INFO] Tajo Catalog Server ............................... SUCCESS [ 11.360 s]
[INFO] Tajo Storage Common ............................... SUCCESS [ 3.058 s]
[INFO] Tajo HDFS Storage ................................. SUCCESS [ 47.324 s]
[INFO] Tajo PullServer ................................... SUCCESS [ 1.315 s]
[INFO] Tajo Client ....................................... SUCCESS [ 2.879 s]
[INFO] Tajo CLI tools .................................... SUCCESS [ 2.297 s]
[INFO] Tajo SQL Parser ................................... SUCCESS [ 4.454 s]
[INFO] ASM (thirdparty) .................................. SUCCESS [ 2.186 s]
[INFO] Tajo RESTful Container ............................ SUCCESS [ 4.178 s]
[INFO] Tajo Metrics ...................................... SUCCESS [ 1.488 s]
[INFO] Tajo Core ......................................... SUCCESS [ 8.097 s]
[INFO] Tajo RPC .......................................... SUCCESS [ 0.966 s]
[INFO] Tajo Catalog Drivers Hive ......................... SUCCESS [ 11.083 s]
[INFO] Tajo Catalog Drivers .............................. SUCCESS [ 0.140 s]
[INFO] Tajo Catalog ...................................... SUCCESS [ 1.150 s]
[INFO] Tajo Client Example ............................... SUCCESS [ 1.067 s]
[INFO] Tajo HBase Storage ................................ SUCCESS [ 3.779 s]
[INFO] Tajo Cluster Tests ................................ SUCCESS [ 2.749 s]
[INFO] Tajo JDBC Driver .................................. SUCCESS [01:03 min]
[INFO] Tajo Storage ...................................... SUCCESS [ 1.013 s]
[INFO] Tajo Distribution ................................. SUCCESS [ 5.644 s]
[INFO] Tajo Core Tests ................................... FAILURE [23:17 min]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 28:04 min
[INFO] Finished at: 2015-09-16T05:21:10+00:00
[INFO] Final Memory: 148M/1755M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.17:test (default-test) on project tajo-core-tests: There are test failures.
[ERROR]
[ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-jdk8-nightly/ws/tajo-core-tests/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-tests
Build step 'Execute shell' marked build as failure
Archiving artifacts
Sending artifact delta relative to Tajo-master-jdk8-nightly #82
Archived 1 artifacts
Archive block size is 32768
Received 0 blocks and 59205911 bytes
Compression is 0.0%
Took 16 sec
Recording test results