See <https://builds.apache.org/job/Tajo-master-build/912/changes>
Changes: [jihoonson] TAJO-1894: Filter condition is ignored when a query involves multiple subqueries and aggregations. [jihoonson] TAJO-1889: UndefinedColumnException when a query with table subquery is executed on self-describing tables. (jihoon) [hyunsik] TAJO-1663: Change the variable name storeType to dataFormat. ------------------------------------------ [...truncated 748519 lines...] 2015-09-28 22:36:14,200 INFO: org.apache.tajo.querymaster.Query (handle(870)) - Processing q_1443478440594_2210 of type STAGE_COMPLETED 2015-09-28 22:36:14,200 INFO: org.apache.tajo.storage.HashShuffleAppenderManager (close(155)) - Close HashShuffleAppender:eb_1443478440594_2210_000002, intermediates=1 2015-09-28 22:36:14,200 INFO: org.apache.tajo.querymaster.Stage (finalizeShuffleReport(1307)) - eb_1443478440594_2210_000002, Finalized HASH_SHUFFLE reports: 1 2015-09-28 22:36:14,200 INFO: org.apache.tajo.querymaster.Stage (transition(1408)) - Stage completed - eb_1443478440594_2210_000002 (total=1, success=1, killed=0) 2015-09-28 22:36:14,200 INFO: org.apache.tajo.querymaster.Query (handle(870)) - Processing q_1443478440594_2210 of type STAGE_COMPLETED 2015-09-28 22:36:14,200 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(163)) - Stopped execution block:eb_1443478440594_2210_000002 2015-09-28 22:36:14,200 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1443478440594_2210_000003 2015-09-28 22:36:14,201 INFO: org.apache.tajo.querymaster.Query (executeNextBlock(772)) - Scheduling Stage:eb_1443478440594_2210_000003 2015-09-28 22:36:14,201 INFO: org.apache.tajo.querymaster.Stage (calculateShuffleOutputNum(1027)) - ============>>>>> Unexpected Case! <<<<<================ 2015-09-28 22:36:14,201 INFO: org.apache.tajo.querymaster.Stage (calculateShuffleOutputNum(1031)) - eb_1443478440594_2210_000003, Table's volume is approximately 1 MB 2015-09-28 22:36:14,201 INFO: org.apache.tajo.querymaster.Stage (calculateShuffleOutputNum(1034)) - eb_1443478440594_2210_000003, The determined number of partitions is 1 2015-09-28 22:36:14,218 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(902)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1443478440594_2210_000003 2015-09-28 22:36:14,218 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleFragmentsForJoinQuery(262)) - [Distributed Join Strategy] : Symmetric Repartition Join 2015-09-28 22:36:14,218 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleSymmetricRepartitionJoin(358)) - Larger intermediate data is approximately 1 MB 2015-09-28 22:36:14,218 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleSymmetricRepartitionJoin(361)) - The calculated number of tasks is 1 2015-09-28 22:36:14,219 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleSymmetricRepartitionJoin(362)) - The number of total shuffle keys is 1 2015-09-28 22:36:14,219 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleSymmetricRepartitionJoin(366)) - The determined number of join tasks is 1 2015-09-28 22:36:14,219 INFO: org.apache.tajo.querymaster.Stage (run(854)) - 1 objects are scheduled 2015-09-28 22:36:14,219 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(135)) - Start TaskScheduler 2015-09-28 22:36:14,221 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(114)) - QueryMaster Address:asf906.gq1.ygridcore.net:32691 2015-09-28 22:36:14,222 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:54920/tajo 2015-09-28 22:36:14,223 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir> 2015-09-28 22:36:14,223 INFO: org.apache.tajo.worker.TaskManager (handle(184)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:3, vCores:2) 2015-09-28 22:36:14,223 INFO: org.apache.tajo.worker.TaskImpl (<init>(116)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/3)> 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (init(197)) - Initializing: ta_1443478440594_2210_000003_000000_00 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - ================================== 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (initPlan(153)) - * Stage ta_1443478440594_2210_000003_000000_00 is initialized 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (initPlan(154)) - * InterQuery: true, Use RANGE_SHUFFLE shuffle, Fragments (num: 4), Fetches (total:2) : 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (initPlan(164)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/3/0_0> 2015-09-28 22:36:14,224 INFO: org.apache.tajo.worker.TaskImpl (initPlan(169)) - ================================== 2015-09-28 22:36:14,225 INFO: org.apache.tajo.worker.TaskImpl (init(216)) - the directory is created <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/in/eb_1443478440594_2210_000003/0/0/eb_1443478440594_2210_000002> 2015-09-28 22:36:14,225 INFO: org.apache.tajo.worker.TaskImpl (init(216)) - the directory is created <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/in/eb_1443478440594_2210_000003/0/0/eb_1443478440594_2210_000001> 2015-09-28 22:36:14,226 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(725)) - Create shuffle Fetchers local:2, remote:0 2015-09-28 22:36:14,226 INFO: org.apache.tajo.worker.TaskImpl (run(617)) - Add a new FileChunk to local chunk list 2015-09-28 22:36:14,226 INFO: org.apache.tajo.worker.TaskImpl (run(617)) - Add a new FileChunk to local chunk list 2015-09-28 22:36:14,226 INFO: org.apache.tajo.worker.TaskImpl (waitForFetch(364)) - ta_1443478440594_2210_000003_000000_00 All fetches are done! 2015-09-28 22:36:14,227 INFO: org.apache.tajo.engine.planner.PhysicalPlannerImpl (createFullOuterHashJoinPlan(622)) - Full Outer Join (6) chooses [Hash Join] 2015-09-28 22:36:14,228 INFO: org.apache.tajo.engine.planner.physical.RangeShuffleFileWriteExec (init(80)) - Output data directory: <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/3/0_0/output> 2015-09-28 22:36:14,250 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(70)) - [ta_1443478440594_2210_000003_000000_00] Chunks creation time: 1 msec 2015-09-28 22:36:14,256 INFO: org.apache.tajo.worker.TaskImpl (run(462)) - ta_1443478440594_2210_000003_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0 2015-09-28 22:36:14,256 INFO: org.apache.tajo.querymaster.Stage (transition(1350)) - Stage - eb_1443478440594_2210_000003 finalize RANGE_SHUFFLE (total=1, success=1, killed=0) 2015-09-28 22:36:14,256 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(164)) - Task Scheduler stopped 2015-09-28 22:36:14,257 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(127)) - TaskScheduler schedulingThread stopped 2015-09-28 22:36:14,257 INFO: org.apache.tajo.querymaster.Stage (transition(1408)) - Stage completed - eb_1443478440594_2210_000003 (total=1, success=1, killed=0) 2015-09-28 22:36:14,257 INFO: org.apache.tajo.querymaster.Query (handle(870)) - Processing q_1443478440594_2210 of type STAGE_COMPLETED 2015-09-28 22:36:14,257 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1443478440594_2210_000004 2015-09-28 22:36:14,257 INFO: org.apache.tajo.querymaster.Query (executeNextBlock(772)) - Scheduling Stage:eb_1443478440594_2210_000004 2015-09-28 22:36:14,257 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(163)) - Stopped execution block:eb_1443478440594_2210_000003 2015-09-28 22:36:14,276 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(902)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1443478440594_2210_000004 2015-09-28 22:36:14,276 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1096)) - eb_1443478440594_2210_000004, Table's volume is approximately 1 MB 2015-09-28 22:36:14,276 INFO: org.apache.tajo.querymaster.Stage (getNonLeafTaskNum(1101)) - eb_1443478440594_2210_000004, The determined number of non-leaf tasks is 1 2015-09-28 22:36:14,277 INFO: org.apache.tajo.querymaster.Repartitioner (scheduleRangeShuffledFetches(673)) - eb_1443478440594_2210_000004, Try to divide [(1,1), (5,3)) into 1 sub ranges (total units: 1) 2015-09-28 22:36:14,277 INFO: org.apache.tajo.engine.utils.TupleUtil (setMaxRangeIfNull(104)) - Set null into range: default.orders.o_orderkey, current tuple is (5,NULL) 2015-09-28 22:36:14,277 INFO: org.apache.tajo.querymaster.Stage (run(854)) - 1 objects are scheduled 2015-09-28 22:36:14,277 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(135)) - Start TaskScheduler 2015-09-28 22:36:14,279 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(114)) - QueryMaster Address:asf906.gq1.ygridcore.net:32691 2015-09-28 22:36:14,281 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:54920/tajo 2015-09-28 22:36:14,281 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir> 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskManager (handle(184)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:3, vCores:2) 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (<init>(116)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/4)> 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (init(197)) - Initializing: ta_1443478440594_2210_000004_000000_00 2015-09-28 22:36:14,282 INFO: org.apache.tajo.storage.FileTablespace (getAppenderFilePath(291)) - Output File Path: hdfs://localhost:54920/tmp/tajo-jenkins/staging/q_1443478440594_2210/RESULT/part-04-000000-000 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (initPlan(147)) - Output File Path: hdfs://localhost:54920/tmp/tajo-jenkins/staging/q_1443478440594_2210/RESULT/part-04-000000-000 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - ================================== 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (initPlan(153)) - * Stage ta_1443478440594_2210_000004_000000_00 is initialized 2015-09-28 22:36:14,282 INFO: org.apache.tajo.worker.TaskImpl (initPlan(154)) - * InterQuery: false, Fragments (num: 1), Fetches (total:1) : 2015-09-28 22:36:14,283 INFO: org.apache.tajo.worker.TaskImpl (initPlan(164)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/4/0_0> 2015-09-28 22:36:14,283 INFO: org.apache.tajo.worker.TaskImpl (initPlan(169)) - ================================== 2015-09-28 22:36:14,283 INFO: org.apache.tajo.worker.TaskImpl (init(216)) - the directory is created <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/in/eb_1443478440594_2210_000004/0/0/eb_1443478440594_2210_000003> 2015-09-28 22:36:14,302 INFO: org.apache.tajo.pullserver.TajoPullServerService (getFileChunks(688)) - GET Request for <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/3/0_0/output/output> (start=(1,1), end=(5,NULL), last=true) 2015-09-28 22:36:14,305 INFO: org.apache.tajo.worker.TaskImpl (getFetchRunners(725)) - Create shuffle Fetchers local:1, remote:0 2015-09-28 22:36:14,305 INFO: org.apache.tajo.worker.TaskImpl (run(617)) - Add a new FileChunk to local chunk list 2015-09-28 22:36:14,306 INFO: org.apache.tajo.worker.TaskImpl (waitForFetch(364)) - ta_1443478440594_2210_000004_000000_00 All fetches are done! 2015-09-28 22:36:14,308 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(70)) - [ta_1443478440594_2210_000004_000000_00] Total merge time: 0 msec 2015-09-28 22:36:14,309 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (close(791)) - Delete file: "fragment": {"id": "eb_1443478440594_2210_000003", "path": <https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/tajo-localdir/q_1443478440594_2210/output/3/0_0/output/output";,> "start": 0,"length": 49} 2015-09-28 22:36:14,312 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49416 is added to blk_1073748687_7863{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-effa63ac-fd5b-40a6-9246-49da495f2301:NORMAL:127.0.0.1:49416|RBW]]} size 0 2015-09-28 22:36:14,313 INFO: org.apache.tajo.worker.TaskImpl (run(462)) - ta_1443478440594_2210_000004_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0 2015-09-28 22:36:14,313 INFO: org.apache.tajo.querymaster.Stage (transition(1350)) - Stage - eb_1443478440594_2210_000004 finalize NONE_SHUFFLE (total=1, success=1, killed=0) 2015-09-28 22:36:14,313 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(164)) - Task Scheduler stopped 2015-09-28 22:36:14,314 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(127)) - TaskScheduler schedulingThread stopped 2015-09-28 22:36:14,314 INFO: org.apache.tajo.querymaster.Stage (transition(1408)) - Stage completed - eb_1443478440594_2210_000004 (total=1, success=1, killed=0) 2015-09-28 22:36:14,314 INFO: org.apache.tajo.querymaster.Query (handle(870)) - Processing q_1443478440594_2210 of type STAGE_COMPLETED 2015-09-28 22:36:14,314 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1443478440594_2210_000005 2015-09-28 22:36:14,314 INFO: org.apache.tajo.querymaster.Query (transition(817)) - Complete Stage[eb_1443478440594_2210_000004], State: SUCCEEDED, 4/4. 2015-09-28 22:36:14,314 INFO: org.apache.tajo.querymaster.Query (handle(870)) - Processing q_1443478440594_2210 of type QUERY_COMPLETED 2015-09-28 22:36:14,314 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(163)) - Stopped execution block:eb_1443478440594_2210_000004 2015-09-28 22:36:14,315 INFO: org.apache.tajo.querymaster.Query (handle(888)) - q_1443478440594_2210 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED 2015-09-28 22:36:14,315 INFO: org.apache.tajo.querymaster.QueryMasterTask (handle(296)) - Query completion notified from q_1443478440594_2210 final state: QUERY_SUCCEEDED 2015-09-28 22:36:14,316 INFO: org.apache.tajo.master.QueryInProgress (heartbeat(259)) - Received QueryMaster heartbeat:q_1443478440594_2210,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf906.gq1.ygridcore.net 2015-09-28 22:36:14,316 INFO: org.apache.tajo.master.QueryManager (stopQuery(279)) - Stop QueryInProgress:q_1443478440594_2210 2015-09-28 22:36:14,316 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(124)) - ========================================================= 2015-09-28 22:36:14,316 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(125)) - Stop query:q_1443478440594_2210 2015-09-28 22:36:14,316 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(172)) - Stopping QueryMasterTask:q_1443478440594_2210 2015-09-28 22:36:14,316 INFO: org.apache.tajo.querymaster.QueryMasterTask (cleanupQuery(473)) - Cleanup resources of all workers. Query: q_1443478440594_2210, workers: 1 2015-09-28 22:36:14,317 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(188)) - Stopped QueryMasterTask:q_1443478440594_2210 2015-09-28 22:36:14,394 INFO: org.apache.tajo.storage.FileTablespace (listStatus(365)) - Total input paths to process : 1 2015-09-28 22:36:14,395 INFO: org.apache.tajo.storage.FileTablespace (getSplits(566)) - Total # of splits: 1 2015-09-28 22:36:14,400 INFO: BlockStateChange (addToInvalidates(1106)) - BLOCK* addToInvalidates: blk_1073748687_7863 127.0.0.1:49416 2015-09-28 22:36:14,401 INFO: org.apache.tajo.master.exec.NonForwardQueryResultFileScanner (close(175)) - "Sent result to client for 6097ee48-6953-4542-9d74-ef20b4c65c51, queryId: q_1443478440594_2210 rows: 5 2015-09-28 22:36:14,403 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session 6097ee48-6953-4542-9d74-ef20b4c65c51 is removed. 2015-09-28 22:36:14,408 INFO: org.apache.tajo.session.SessionManager (createSession(79)) - Session 89b98724-aef6-467e-94ed-003aa1a8c737 is created. 2015-09-28 22:36:14,410 INFO: org.apache.tajo.master.GlobalEngine (executeQuery(176)) - Query: create table "TEST_DESC_TABLE" (col1 int4, col2 int4) 2015-09-28 22:36:14,411 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(280)) - Non Optimized Query: ----------------------------- Query Block Graph ----------------------------- |-#ROOT ----------------------------- Optimization Log: ----------------------------- 2015-09-28 22:36:14,411 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(282)) - ============================================= 2015-09-28 22:36:14,411 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(283)) - Optimized Query: ----------------------------- Query Block Graph ----------------------------- |-#ROOT ----------------------------- Optimization Log: ----------------------------- 2015-09-28 22:36:14,411 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(284)) - ============================================= 2015-09-28 22:36:14,415 INFO: org.apache.tajo.catalog.CatalogServer (createTable(689)) - relation "default.TEST_DESC_TABLE" is added to the catalog (127.0.0.1:32685) 2015-09-28 22:36:14,415 INFO: org.apache.tajo.master.exec.DDLExecutor (create(114)) - relation 'default.TEST_DESC_TABLE' created. 2015-09-28 22:36:14,419 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session 89b98724-aef6-467e-94ed-003aa1a8c737 is removed. Tests run: 22, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 5.801 sec - in org.apache.tajo.cli.tsql.TestTajoCli Sep 28, 2015 10:24:03 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:03 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:19 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:19 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:19 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:19 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:19 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers Sep 28, 2015 10:24:22 PM INFO: parquet.hadoop.ParquetFileReader: reading another 1 footers 2015-09-28 22:36:14,427 INFO: org.mortbay.log (invoke0(?)) - Shutdown hook executing 2015-09-28 22:36:14,427 INFO: org.mortbay.log (invoke(?)) - Shutdown hook complete 2015-09-28 22:36:14,430 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session 2923821f-02ba-421c-8897-5b0880519fba is removed. 2015-09-28 22:36:14,434 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session c931d75a-fa0b-4c4e-8d3a-878ade338c46 is removed. 2015-09-28 22:36:14,436 INFO: org.apache.tajo.worker.TajoWorker (run(565)) - ============================================ 2015-09-28 22:36:14,436 INFO: org.apache.tajo.worker.TajoWorker (run(566)) - TajoWorker received SIGINT Signal 2015-09-28 22:36:14,437 INFO: org.apache.tajo.worker.TajoWorker (run(567)) - ============================================ 2015-09-28 22:36:14,440 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped 2015-09-28 22:36:14,442 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_asf906.gq1.ygridcore.net_32689 stopped. 2015-09-28 22:36:14,471 INFO: org.apache.tajo.worker.NodeStatusUpdater (serviceStop(115)) - NodeStatusUpdater stopped. 2015-09-28 22:36:14,471 INFO: org.apache.tajo.worker.NodeStatusUpdater (run(265)) - Heartbeat Thread stopped. 2015-09-28 22:36:14,475 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:32691) shutdown 2015-09-28 22:36:14,477 INFO: org.apache.tajo.querymaster.QueryMasterManagerService (serviceStop(106)) - QueryMasterManagerService stopped 2015-09-28 22:36:14,477 INFO: org.apache.tajo.querymaster.QueryMaster (run(427)) - QueryMaster heartbeat thread stopped 2015-09-28 22:36:14,478 INFO: org.apache.tajo.querymaster.QueryMaster (serviceStop(162)) - QueryMaster stopped 2015-09-28 22:36:14,478 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(98)) - TajoWorkerClientService stopping 2015-09-28 22:36:14,478 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:32690) shutdown 2015-09-28 22:36:14,479 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(102)) - TajoWorkerClientService stopped 2015-09-28 22:36:14,479 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:32689) shutdown 2015-09-28 22:36:14,479 INFO: org.apache.tajo.worker.TajoWorkerManagerService (serviceStop(93)) - TajoWorkerManagerService stopped 2015-09-28 22:36:14,480 INFO: org.apache.tajo.worker.TajoWorker (serviceStop(375)) - TajoWorker main thread exiting 2015-09-28 22:36:15,737 INFO: BlockStateChange (invalidateWorkForOneNode(3488)) - BLOCK* BlockManager: ask 127.0.0.1:49416 to delete [blk_1073748683_7859, blk_1073748687_7863] 2015-09-28 22:36:18,889 INFO: org.apache.tajo.master.TajoMaster (run(580)) - ============================================ 2015-09-28 22:36:18,889 INFO: org.apache.tajo.master.TajoMaster (run(581)) - TajoMaster received SIGINT Signal 2015-09-28 22:36:18,889 INFO: org.apache.tajo.master.TajoMaster (run(582)) - ============================================ 2015-09-28 22:36:18,890 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (Tajo-REST) listened on 0:0:0:0:0:0:0:0:32688) shutdown 2015-09-28 22:36:18,890 INFO: org.apache.tajo.ws.rs.TajoRestService (serviceStop(129)) - Tajo Rest Service stopped. 2015-09-28 22:36:18,893 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_127.0.0.1_32687 stopped. 2015-09-28 22:36:18,898 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49416 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1502211b-dd8a-4fba-846b-4984370bcab2:NORMAL:127.0.0.1:49416|RBW]]} size 524 2015-09-28 22:36:18,898 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (QueryCoordinatorProtocol) listened on 127.0.0.1:32687) shutdown 2015-09-28 22:36:18,899 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped 2015-09-28 22:36:18,900 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (TajoMasterClientProtocol) listened on 127.0.0.1:32686) shutdown 2015-09-28 22:36:18,901 INFO: org.apache.tajo.catalog.CatalogServer (serviceStop(188)) - Catalog Server (127.0.0.1:32685) shutdown 2015-09-28 22:36:18,902 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (CatalogProtocol) listened on 127.0.0.1:32685) shutdown 2015-09-28 22:36:18,902 INFO: org.apache.tajo.catalog.store.DerbyStore (close(3157)) - Close database (jdbc:derby:memory:<https://builds.apache.org/job/Tajo-master-build/ws/tajo-core-tests/target/test-data/a5e2e0e6-d47b-4a20-b6b9-f77af62b0a53/db;create=true)> 2015-09-28 22:36:18,903 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(173)) - Rpc (TajoResourceTrackerProtocol) listened on 127.0.0.1:32684) shutdown 2015-09-28 22:36:18,904 INFO: org.apache.tajo.master.TajoMaster (serviceStop(440)) - Tajo Master main thread exiting 2015-09-28 22:36:19,130 INFO: org.apache.tajo.catalog.store.DerbyStore (shutdown(68)) - Derby shutdown complete normally. 2015-09-28 22:36:19,130 INFO: org.apache.tajo.catalog.store.DerbyStore (shutdown(75)) - Shutdown database Results : Failed tests: TestQueryOnSelfDescTable.testTableSubquery3:130->QueryTestCaseBase.runSimpleTests:617 Result Verification for: 1 th test expected:<...------------------- [example glossary,1,null,SGML,ISO 8879:1986 ]> but was:<...------------------- []> Tests run: 1689, Failures: 1, Errors: 0, Skipped: 0 [INFO] ------------------------------------------------------------------------ [INFO] Reactor Summary: [INFO] [INFO] Tajo Main ......................................... SUCCESS [ 1.603 s] [INFO] Tajo Project POM .................................. SUCCESS [ 1.196 s] [INFO] Tajo Maven Plugins ................................ SUCCESS [ 2.414 s] [INFO] Tajo Common ....................................... SUCCESS [ 30.908 s] [INFO] Tajo Algebra ...................................... SUCCESS [ 2.214 s] [INFO] Tajo Catalog Common ............................... SUCCESS [ 5.319 s] [INFO] Tajo Plan ......................................... SUCCESS [ 6.701 s] [INFO] Tajo Rpc Common ................................... SUCCESS [ 1.181 s] [INFO] Tajo Protocol Buffer Rpc .......................... SUCCESS [ 50.450 s] [INFO] Tajo Catalog Client ............................... SUCCESS [ 1.366 s] [INFO] Tajo Catalog Server ............................... SUCCESS [ 11.044 s] [INFO] Tajo Storage Common ............................... SUCCESS [ 2.432 s] [INFO] Tajo HDFS Storage ................................. SUCCESS [ 48.085 s] [INFO] Tajo PullServer ................................... SUCCESS [ 0.839 s] [INFO] Tajo Client ....................................... SUCCESS [ 2.742 s] [INFO] Tajo CLI tools .................................... SUCCESS [ 1.632 s] [INFO] Tajo SQL Parser ................................... SUCCESS [ 3.672 s] [INFO] ASM (thirdparty) .................................. SUCCESS [ 1.866 s] [INFO] Tajo RESTful Container ............................ SUCCESS [ 3.546 s] [INFO] Tajo Metrics ...................................... SUCCESS [ 1.326 s] [INFO] Tajo Core ......................................... SUCCESS [ 6.260 s] [INFO] Tajo RPC .......................................... SUCCESS [ 0.910 s] [INFO] Tajo Catalog Drivers Hive ......................... SUCCESS [ 11.395 s] [INFO] Tajo Catalog Drivers .............................. SUCCESS [ 0.043 s] [INFO] Tajo Catalog ...................................... SUCCESS [ 0.964 s] [INFO] Tajo Client Example ............................... SUCCESS [ 1.016 s] [INFO] Tajo HBase Storage ................................ SUCCESS [ 3.551 s] [INFO] Tajo Cluster Tests ................................ SUCCESS [ 2.275 s] [INFO] Tajo JDBC Driver .................................. SUCCESS [ 33.525 s] [INFO] Tajo JDBC storage common .......................... SUCCESS [ 0.793 s] [INFO] Tajo PostgreSQL JDBC storage ...................... SUCCESS [ 37.517 s] [INFO] Tajo Storage ...................................... SUCCESS [ 1.010 s] [INFO] Tajo Distribution ................................. SUCCESS [ 5.255 s] [INFO] Tajo Core Tests ................................... FAILURE [22:29 min] [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 27:14 min [INFO] Finished at: 2015-09-28T22:36:19+00:00 [INFO] Final Memory: 155M/1831M [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-build/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 Updating TAJO-1663 Updating TAJO-1894 Updating TAJO-1889
