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/11/10 10:38:40 UTC
Build failed in Jenkins: Tajo-master-build #973
See <https://builds.apache.org/job/Tajo-master-build/973/changes>
Changes:
[jhkim] TAJO-1965: TestBlockingRpc::testServerShutdown occassionally fails.
------------------------------------------
[...truncated 10883 lines...]
2015-11-10 09:38:51,816 INFO: org.apache.tajo.querymaster.Query (<init>(234)) -
=======================================================
The order of execution:
1: eb_1447148300849_0034_000001
2: eb_1447148300849_0034_000002
=======================================================
2015-11-10 09:38:51,816 INFO: org.apache.hadoop.yarn.event.AsyncDispatcher (register(200)) - Registering class org.apache.tajo.master.event.QueryEventType for class org.apache.tajo.querymaster.Query
2015-11-10 09:38:51,821 INFO: org.apache.tajo.querymaster.Query (handle(868)) - Processing q_1447148300849_0034 of type START
2015-11-10 09:38:51,823 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (first(84)) - Initial executable blocks [eb_1447148300849_0034_000001]
2015-11-10 09:38:51,823 INFO: org.apache.tajo.querymaster.Query (handle(886)) - q_1447148300849_0034 Query Transitioned from QUERY_NEW to QUERY_RUNNING
2015-11-10 09:38:51,848 INFO: org.apache.tajo.querymaster.Stage (initTaskScheduler(901)) - org.apache.tajo.querymaster.DefaultTaskScheduler is chosen for the task scheduling for eb_1447148300849_0034_000001
2015-11-10 09:38:51,850 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tajo/warehouse/lineitem dst=null perm=null proto=rpc
2015-11-10 09:38:51,852 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tajo/warehouse/lineitem dst=null perm=null proto=rpc
2015-11-10 09:38:51,853 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=listStatus src=/tajo/warehouse/lineitem dst=null perm=null proto=rpc
2015-11-10 09:38:51,854 INFO: org.apache.tajo.storage.FileTablespace (listStatus(363)) - Total input paths to process : 1
2015-11-10 09:38:51,855 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tajo/warehouse/lineitem/lineitem.tbl dst=null perm=null proto=rpc
2015-11-10 09:38:51,856 INFO: org.apache.tajo.storage.FileTablespace (getSplits(564)) - Total # of splits: 1
2015-11-10 09:38:51,856 INFO: org.apache.tajo.querymaster.Stage (run(853)) - 1 objects are scheduled
2015-11-10 09:38:51,857 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (start(134)) - Start TaskScheduler
2015-11-10 09:38:51,857 INFO: org.apache.hadoop.yarn.util.RackResolver (coreResolve(109)) - Resolved 127.0.0.1 to /default-rack
2015-11-10 09:38:51,860 INFO: org.apache.hadoop.yarn.util.RackResolver (coreResolve(109)) - Resolved asf905.gq1.ygridcore.net to /default-rack
2015-11-10 09:38:51,861 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (increaseConcurrency(525)) - Assigned host : 127.0.0.1, Unknown Volume : -1, Concurrency : 1
2015-11-10 09:38:51,863 INFO: org.apache.tajo.worker.TaskManager (createExecutionBlock(114)) - QueryMaster Address:asf905.gq1.ygridcore.net:11377
2015-11-10 09:38:51,864 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (assignToLeafTasks(922)) - Assigned Local/Rack/Total: (0/1/1), Attempted Cancel/Assign/Total: (0/1/1), Locality: 0.00%, Rack host: asf905.gq1.ygridcore.net
2015-11-10 09:38:51,867 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(119)) - Tajo Root Dir: hdfs://localhost:39024/tajo
2015-11-10 09:38:51,867 INFO: org.apache.tajo.worker.ExecutionBlockContext (init(120)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/tajo-localdir>
2015-11-10 09:38:51,869 INFO: org.apache.tajo.worker.TaskManager (handle(184)) - Running ExecutionBlocks: 1, running tasks:0, availableResource: (Memory:1000, Disks:2, vCores:2)
2015-11-10 09:38:52,173 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033 dst=null perm=null proto=rpc
2015-11-10 09:38:52,175 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=mkdirs src=/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033 dst=null perm=jenkins:supergroup:rwxr-xr-x proto=rpc
2015-11-10 09:38:52,175 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(365)) - Saving query summary: hdfs://localhost:39024/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/query.hist
2015-11-10 09:38:52,176 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/query.hist dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-10 09:38:52,178 INFO: org.apache.hadoop.hdfs.StateChange (saveAllocatedBlock(3575)) - BLOCK* allocate blk_1073741881_1057{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-8e7f657e-a079-4bb6-9b9e-3a7e75665a0d:NORMAL:127.0.0.1:49483|RBW]]} for /tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/query.hist
2015-11-10 09:38:52,180 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (writeBlock(655)) - Receiving BP-1359676671-67.195.81.149-1447148296033:blk_1073741881_1057 src: /127.0.0.1:36781 dest: /127.0.0.1:49483
2015-11-10 09:38:52,262 INFO: org.apache.tajo.worker.TaskImpl (<init>(116)) - Task basedir is created (<https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/tajo-localdir/q_1447148300849_0034/output/1)>
2015-11-10 09:38:52,263 INFO: org.apache.tajo.worker.TaskImpl (init(197)) - Initializing: ta_1447148300849_0034_000001_000000_00
2015-11-10 09:38:52,263 INFO: org.apache.tajo.storage.FileTablespace (getAppenderFilePath(289)) - Output File Path: hdfs://localhost:39024/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000
2015-11-10 09:38:52,263 INFO: org.apache.tajo.worker.TaskImpl (initPlan(147)) - Output File Path: hdfs://localhost:39024/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000
2015-11-10 09:38:52,263 INFO: org.apache.tajo.worker.TaskImpl (initPlan(152)) - ==================================
2015-11-10 09:38:52,264 INFO: org.apache.tajo.worker.TaskImpl (initPlan(153)) - * Stage ta_1447148300849_0034_000001_000000_00 is initialized
2015-11-10 09:38:52,264 INFO: org.apache.tajo.worker.TaskImpl (initPlan(154)) - * InterQuery: false, Fragments (num: 1), Fetches (total:0) :
2015-11-10 09:38:52,264 INFO: org.apache.tajo.worker.TaskImpl (initPlan(164)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/tajo-localdir/q_1447148300849_0034/output/1/0_0>
2015-11-10 09:38:52,264 INFO: org.apache.tajo.worker.TaskImpl (initPlan(169)) - ==================================
2015-11-10 09:38:52,267 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tajo/warehouse/lineitem/lineitem.tbl dst=null perm=null proto=rpc
2015-11-10 09:38:52,297 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000 dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-10 09:38:52,297 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace (finalizeBlock(1375)) - src: /127.0.0.1:36781, dest: /127.0.0.1:49483, bytes: 6073, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_204668807_1, offset: 0, srvID: f1de00d2-942b-4e13-9cc7-a82ba1e5aa3d, blockid: BP-1359676671-67.195.81.149-1447148296033:blk_1073741881_1057, duration: 1327485
2015-11-10 09:38:52,298 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (run(1348)) - PacketResponder: BP-1359676671-67.195.81.149-1447148296033:blk_1073741881_1057, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-10 09:38:52,298 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49483 is added to blk_1073741881_1057{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-2293c166-84a0-4b8d-b650-2699b2f14211:NORMAL:127.0.0.1:49483|FINALIZED]]} size 0
2015-11-10 09:38:52,299 INFO: org.apache.hadoop.hdfs.StateChange (completeFile(3495)) - DIR* completeFile: /tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/query.hist is closed by DFSClient_NONMAPREDUCE_204668807_1
2015-11-10 09:38:52,301 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/eb_1447148300849_0033_000001.hist dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-10 09:38:52,301 INFO: org.apache.hadoop.hdfs.StateChange (saveAllocatedBlock(3575)) - BLOCK* allocate blk_1073741882_1058{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-8e7f657e-a079-4bb6-9b9e-3a7e75665a0d:NORMAL:127.0.0.1:49483|RBW]]} for /tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000
2015-11-10 09:38:52,302 INFO: org.apache.tajo.util.history.HistoryWriter (writeQueryHistory(379)) - Saving query unit: hdfs://localhost:39024/tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/eb_1447148300849_0033_000001.hist
2015-11-10 09:38:52,303 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (writeBlock(655)) - Receiving BP-1359676671-67.195.81.149-1447148296033:blk_1073741882_1058 src: /127.0.0.1:36783 dest: /127.0.0.1:49483
2015-11-10 09:38:52,303 INFO: org.apache.hadoop.hdfs.StateChange (saveAllocatedBlock(3575)) - BLOCK* allocate blk_1073741883_1059{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-8e7f657e-a079-4bb6-9b9e-3a7e75665a0d:NORMAL:127.0.0.1:49483|RBW]]} for /tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/eb_1447148300849_0033_000001.hist
2015-11-10 09:38:52,305 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (writeBlock(655)) - Receiving BP-1359676671-67.195.81.149-1447148296033:blk_1073741883_1059 src: /127.0.0.1:36784 dest: /127.0.0.1:49483
2015-11-10 09:38:52,305 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace (finalizeBlock(1375)) - src: /127.0.0.1:36783, dest: /127.0.0.1:49483, bytes: 66, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_204668807_1, offset: 0, srvID: f1de00d2-942b-4e13-9cc7-a82ba1e5aa3d, blockid: BP-1359676671-67.195.81.149-1447148296033:blk_1073741882_1058, duration: 846058
2015-11-10 09:38:52,305 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (run(1348)) - PacketResponder: BP-1359676671-67.195.81.149-1447148296033:blk_1073741882_1058, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-10 09:38:52,306 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49483 is added to blk_1073741882_1058{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-8e7f657e-a079-4bb6-9b9e-3a7e75665a0d:NORMAL:127.0.0.1:49483|RBW]]} size 0
2015-11-10 09:38:52,306 INFO: org.apache.hadoop.hdfs.StateChange (completeFile(3495)) - DIR* completeFile: /tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000 is closed by DFSClient_NONMAPREDUCE_204668807_1
2015-11-10 09:38:52,306 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace (finalizeBlock(1375)) - src: /127.0.0.1:36784, dest: /127.0.0.1:49483, bytes: 518, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_204668807_1, offset: 0, srvID: f1de00d2-942b-4e13-9cc7-a82ba1e5aa3d, blockid: BP-1359676671-67.195.81.149-1447148296033:blk_1073741883_1059, duration: 1021143
2015-11-10 09:38:52,307 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (run(1348)) - PacketResponder: BP-1359676671-67.195.81.149-1447148296033:blk_1073741883_1059, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-10 09:38:52,307 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49483 is added to blk_1073741883_1059{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-2293c166-84a0-4b8d-b650-2699b2f14211:NORMAL:127.0.0.1:49483|RBW]]} size 0
2015-11-10 09:38:52,308 INFO: org.apache.tajo.querymaster.Stage (transition(1349)) - Stage - eb_1447148300849_0034_000001 finalize NONE_SHUFFLE (total=1, success=1, killed=0)
2015-11-10 09:38:52,308 INFO: org.apache.hadoop.hdfs.StateChange (completeFile(3495)) - DIR* completeFile: /tmp/tajo-jenkins/staging/history/20151110/query-detail/q_1447148300849_0033/eb_1447148300849_0033_000001.hist is closed by DFSClient_NONMAPREDUCE_204668807_1
2015-11-10 09:38:52,307 INFO: org.apache.tajo.worker.TaskImpl (run(462)) - ta_1447148300849_0034_000001_000000_00 completed. Worker's task counter - total:1, succeeded: 1, killed: 0, failed: 0
2015-11-10 09:38:52,308 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (run(126)) - TaskScheduler schedulingThread stopped
2015-11-10 09:38:52,308 INFO: org.apache.tajo.querymaster.DefaultTaskScheduler (stop(163)) - Task Scheduler stopped
2015-11-10 09:38:52,309 INFO: org.apache.tajo.querymaster.Stage (transition(1407)) - Stage completed - eb_1447148300849_0034_000001 (total=1, success=1, killed=0)
2015-11-10 09:38:52,310 INFO: org.apache.tajo.querymaster.Query (handle(868)) - Processing q_1447148300849_0034 of type STAGE_COMPLETED
2015-11-10 09:38:52,310 INFO: org.apache.tajo.worker.TaskManager (stopExecutionBlock(163)) - Stopped execution block:eb_1447148300849_0034_000001
2015-11-10 09:38:52,310 INFO: org.apache.tajo.engine.planner.global.ParallelExecutionQueue (next(95)) - Next executable block eb_1447148300849_0034_000002
2015-11-10 09:38:52,310 INFO: org.apache.tajo.querymaster.Query (transition(815)) - Complete Stage[eb_1447148300849_0034_000001], State: SUCCEEDED, 1/1.
2015-11-10 09:38:52,310 INFO: org.apache.tajo.querymaster.Query (handle(868)) - Processing q_1447148300849_0034 of type QUERY_COMPLETED
2015-11-10 09:38:52,312 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=contentSummary src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT dst=null perm=null proto=rpc
2015-11-10 09:38:52,312 INFO: org.apache.tajo.querymaster.Query (handle(886)) - q_1447148300849_0034 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2015-11-10 09:38:52,312 INFO: org.apache.tajo.querymaster.QueryMasterTask (handle(296)) - Query completion notified from q_1447148300849_0034 final state: QUERY_SUCCEEDED
2015-11-10 09:38:52,313 INFO: org.apache.tajo.master.QueryInProgress (heartbeat(259)) - Received QueryMaster heartbeat:q_1447148300849_0034,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf905.gq1.ygridcore.net
2015-11-10 09:38:52,313 INFO: org.apache.tajo.master.QueryManager (stopQuery(279)) - Stop QueryInProgress:q_1447148300849_0034
2015-11-10 09:38:52,313 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(124)) - =========================================================
2015-11-10 09:38:52,314 INFO: org.apache.tajo.master.QueryInProgress (stopProgress(125)) - Stop query:q_1447148300849_0034
2015-11-10 09:38:52,313 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(172)) - Stopping QueryMasterTask:q_1447148300849_0034
2015-11-10 09:38:52,314 INFO: org.apache.tajo.querymaster.QueryMasterTask (cleanupQuery(473)) - Cleanup resources of all workers. Query: q_1447148300849_0034, workers: 1
2015-11-10 09:38:52,314 INFO: org.apache.tajo.querymaster.QueryMasterTask (serviceStop(188)) - Stopped QueryMasterTask:q_1447148300849_0034
2015-11-10 09:38:52,595 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT dst=null perm=null proto=rpc
2015-11-10 09:38:52,596 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT dst=null perm=null proto=rpc
2015-11-10 09:38:52,597 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=listStatus src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT dst=null perm=null proto=rpc
2015-11-10 09:38:52,598 INFO: org.apache.tajo.storage.FileTablespace (listStatus(363)) - Total input paths to process : 1
2015-11-10 09:38:52,598 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000 dst=null perm=null proto=rpc
2015-11-10 09:38:52,599 INFO: org.apache.tajo.storage.FileTablespace (getSplits(564)) - Total # of splits: 1
2015-11-10 09:38:52,602 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/tajo-jenkins/staging/q_1447148300849_0034/RESULT/part-01-000000-000 dst=null perm=null proto=rpc
2015-11-10 09:38:52,608 INFO: BlockStateChange (addToInvalidates(1106)) - BLOCK* addToInvalidates: blk_1073741882_1058 127.0.0.1:49483
2015-11-10 09:38:52,608 INFO: org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit (logAuditMessage(8264)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=delete src=/tmp/tajo-jenkins/staging/q_1447148300849_0034 dst=null perm=null proto=rpc
2015-11-10 09:38:52,609 INFO: org.apache.tajo.master.exec.NonForwardQueryResultFileScanner (close(175)) - "Sent result to client for 1e2d11fb-b3c8-4c05-962e-7af61c3614b0, queryId: q_1447148300849_0034 rows: 2
2015-11-10 09:38:52,611 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session 1e2d11fb-b3c8-4c05-962e-7af61c3614b0 is removed.
2015-11-10 09:38:52,613 INFO: org.apache.tajo.master.GlobalEngine (updateQuery(239)) - SQL: DROP TABLE IF EXISTS "TestTajoJdbc".table1
2015-11-10 09:38:52,614 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(280)) - Non Optimized Query:
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
2015-11-10 09:38:52,614 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(282)) - =============================================
2015-11-10 09:38:52,614 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(283)) - Optimized Query:
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
2015-11-10 09:38:52,614 INFO: org.apache.tajo.master.GlobalEngine (createLogicalPlan(284)) - =============================================
2015-11-10 09:38:52,615 INFO: org.apache.tajo.master.exec.DDLExecutor (dropTable(310)) - relation "TestTajoJdbc.table1" is already exists.
2015-11-10 09:38:52,621 INFO: org.apache.tajo.session.SessionManager (removeSession(85)) - Session 3c3dcd6a-fbd1-4af0-89fe-5b510c61615f is removed.
Tests run: 12, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 19.61 sec <<< FAILURE! - in org.apache.tajo.jdbc.TestTajoJdbc
testCancel(org.apache.tajo.jdbc.TestTajoJdbc) Time elapsed: 11.063 sec <<< FAILURE!
java.lang.AssertionError: expected:<QUERY_KILLED> but was:<QUERY_FAILED>
at org.apache.tajo.jdbc.TestTajoJdbc.testCancel(TestTajoJdbc.java:674)
2015-11-10 09:38:52,629 INFO: org.apache.tajo.worker.TajoWorker (run(564)) - ============================================
2015-11-10 09:38:52,629 INFO: org.apache.tajo.worker.TajoWorker (run(565)) - TajoWorker received SIGINT Signal
2015-11-10 09:38:52,629 INFO: org.apache.tajo.worker.TajoWorker (run(566)) - ============================================
2015-11-10 09:38:52,631 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_asf905.gq1.ygridcore.net_11375 stopped.
2015-11-10 09:38:52,631 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped
2015-11-10 09:38:52,633 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace (finalizeBlock(1375)) - src: /127.0.0.1:36507, dest: /127.0.0.1:49483, bytes: 29691, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_204668807_1, offset: 0, srvID: f1de00d2-942b-4e13-9cc7-a82ba1e5aa3d, blockid: BP-1359676671-67.195.81.149-1447148296033:blk_1073741834_1010, duration: 23576770315
2015-11-10 09:38:52,633 INFO: org.apache.hadoop.hdfs.server.datanode.DataNode (run(1348)) - PacketResponder: BP-1359676671-67.195.81.149-1447148296033:blk_1073741834_1010, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-10 09:38:52,635 INFO: BlockStateChange (logAddStoredBlock(2624)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:49483 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-8e7f657e-a079-4bb6-9b9e-3a7e75665a0d:NORMAL:127.0.0.1:49483|RBW]]} size 509
2015-11-10 09:38:52,659 INFO: org.apache.hadoop.hdfs.StateChange (completeFile(3495)) - DIR* completeFile: /tmp/tajo-jenkins/staging/history/20151110/query-list/query-list-093829.hist is closed by DFSClient_NONMAPREDUCE_204668807_1
2015-11-10 09:38:52,661 INFO: org.apache.tajo.worker.NodeStatusUpdater (serviceStop(115)) - NodeStatusUpdater stopped.
2015-11-10 09:38:52,662 INFO: org.apache.tajo.worker.NodeStatusUpdater (run(265)) - Heartbeat Thread stopped.
2015-11-10 09:38:52,663 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:11377) shutdown
2015-11-10 09:38:52,663 INFO: org.apache.tajo.querymaster.QueryMasterManagerService (serviceStop(106)) - QueryMasterManagerService stopped
2015-11-10 09:38:52,664 INFO: org.apache.tajo.querymaster.QueryMaster (run(427)) - QueryMaster heartbeat thread stopped
2015-11-10 09:38:52,665 INFO: org.apache.tajo.querymaster.QueryMaster (serviceStop(162)) - QueryMaster stopped
2015-11-10 09:38:52,665 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(98)) - TajoWorkerClientService stopping
2015-11-10 09:38:52,666 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:11376) shutdown
2015-11-10 09:38:52,666 INFO: org.apache.tajo.worker.TajoWorkerClientService (stop(102)) - TajoWorkerClientService stopped
2015-11-10 09:38:52,666 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:11375) shutdown
2015-11-10 09:38:52,666 INFO: org.apache.tajo.worker.TajoWorkerManagerService (serviceStop(93)) - TajoWorkerManagerService stopped
2015-11-10 09:38:52,666 INFO: org.apache.tajo.worker.TajoWorker (serviceStop(374)) - TajoWorker main thread exiting
2015-11-10 09:38:53,518 ERROR: org.apache.tajo.util.history.HistoryWriter (writeHistory(330)) - Error while saving query summary: q_1447148300849_0034:null
java.nio.channels.ClosedChannelException
at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:1521)
at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:104)
at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:58)
at java.io.DataOutputStream.write(DataOutputStream.java:107)
at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
at org.apache.tajo.util.history.HistoryWriter$WriterThread.writeQuerySummary(HistoryWriter.java:406)
at org.apache.tajo.util.history.HistoryWriter$WriterThread.writeHistory(HistoryWriter.java:328)
at org.apache.tajo.util.history.HistoryWriter$WriterThread.run(HistoryWriter.java:244)
2015-11-10 09:38:53,577 INFO: BlockStateChange (invalidateWorkForOneNode(3488)) - BLOCK* BlockManager: ask 127.0.0.1:49483 to delete [blk_1073741875_1051, blk_1073741880_1056, blk_1073741882_1058]
2015-11-10 09:38:54,136 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (deleteAsync(217)) - Scheduling blk_1073741875_1051 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data1/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741875> for deletion
2015-11-10 09:38:54,136 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (deleteAsync(217)) - Scheduling blk_1073741880_1056 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data2/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741880> for deletion
2015-11-10 09:38:54,136 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (deleteAsync(217)) - Scheduling blk_1073741882_1058 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data2/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741882> for deletion
2015-11-10 09:38:54,136 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (run(295)) - Deleted BP-1359676671-67.195.81.149-1447148296033 blk_1073741875_1051 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data1/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741875>
2015-11-10 09:38:54,137 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (run(295)) - Deleted BP-1359676671-67.195.81.149-1447148296033 blk_1073741880_1056 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data2/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741880>
2015-11-10 09:38:54,137 INFO: org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService (run(295)) - Deleted BP-1359676671-67.195.81.149-1447148296033 blk_1073741882_1058 file <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/data/data2/current/BP-1359676671-67.195.81.149-1447148296033/current/finalized/subdir0/subdir0/blk_1073741882>
2015-11-10 09:38:54,870 INFO: org.apache.tajo.master.TajoMaster (run(577)) - ============================================
2015-11-10 09:38:54,870 INFO: org.apache.tajo.master.TajoMaster (run(578)) - TajoMaster received SIGINT Signal
2015-11-10 09:38:54,871 INFO: org.apache.tajo.master.TajoMaster (run(579)) - ============================================
2015-11-10 09:38:54,873 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (Tajo-REST) listened on 0:0:0:0:0:0:0:0:11374) shutdown
2015-11-10 09:38:54,873 INFO: org.apache.tajo.ws.rs.TajoRestService (serviceStop(129)) - Tajo Rest Service stopped.
2015-11-10 09:38:54,873 INFO: org.apache.tajo.util.history.HistoryWriter (run(275)) - HistoryWriter_127.0.0.1_11373 stopped.
2015-11-10 09:38:54,873 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (QueryCoordinatorProtocol) listened on 127.0.0.1:11373) shutdown
2015-11-10 09:38:54,873 INFO: org.apache.tajo.util.history.HistoryCleaner (run(136)) - History cleaner stopped
2015-11-10 09:38:54,874 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (TajoMasterClientProtocol) listened on 127.0.0.1:11372) shutdown
2015-11-10 09:38:54,876 INFO: org.apache.tajo.catalog.CatalogServer (serviceStop(185)) - Catalog Server (127.0.0.1:11371) shutdown
2015-11-10 09:38:54,876 INFO: org.apache.hadoop.yarn.util.AbstractLivelinessMonitor (run(135)) - SessionLivelinessMonitor thread interrupted
2015-11-10 09:38:54,876 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (CatalogProtocol) listened on 127.0.0.1:11371) shutdown
2015-11-10 09:38:54,876 INFO: org.apache.tajo.catalog.store.DerbyStore (close(2979)) - Close database (jdbc:derby:memory:<https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/target/test-data/e90133a0-b4a5-44fa-a193-fcf156173f1a/db;create=true)>
2015-11-10 09:38:54,877 INFO: org.apache.tajo.rpc.NettyServerBase (shutdown(171)) - Rpc (TajoResourceTrackerProtocol) listened on 127.0.0.1:11370) shutdown
2015-11-10 09:38:54,877 INFO: org.apache.tajo.master.TajoMaster (serviceStop(437)) - Tajo Master main thread exiting
2015-11-10 09:38:54,877 INFO: org.apache.hadoop.yarn.util.AbstractLivelinessMonitor (run(135)) - NodeLivelinessMonitor thread interrupted
2015-11-10 09:38:54,907 INFO: org.apache.tajo.catalog.store.DerbyStore (shutdown(68)) - Derby shutdown complete normally.
2015-11-10 09:38:54,907 INFO: org.apache.tajo.catalog.store.DerbyStore (shutdown(75)) - Shutdown database
Results :
Failed tests:
TestTajoJdbc.testCancel:674 expected:<QUERY_KILLED> but was:<QUERY_FAILED>
Tests run: 37, Failures: 1, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [ 2.440 s]
[INFO] Tajo Project POM .................................. SUCCESS [ 1.990 s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [ 4.788 s]
[INFO] Tajo Common ....................................... SUCCESS [ 33.767 s]
[INFO] Tajo Algebra ...................................... SUCCESS [ 3.264 s]
[INFO] Tajo Catalog Common ............................... SUCCESS [ 5.873 s]
[INFO] Tajo Plan ......................................... SUCCESS [ 10.122 s]
[INFO] Tajo Rpc Common ................................... SUCCESS [ 1.553 s]
[INFO] Tajo Protocol Buffer Rpc .......................... SUCCESS [02:31 min]
[INFO] Tajo Catalog Client ............................... SUCCESS [ 1.672 s]
[INFO] Tajo Catalog Server ............................... SUCCESS [01:32 min]
[INFO] Tajo Storage Common ............................... SUCCESS [ 4.843 s]
[INFO] Tajo HDFS Storage ................................. SUCCESS [01:10 min]
[INFO] Tajo PullServer ................................... SUCCESS [ 1.479 s]
[INFO] Tajo Client ....................................... SUCCESS [ 3.316 s]
[INFO] Tajo CLI tools .................................... SUCCESS [ 4.396 s]
[INFO] Tajo SQL Parser ................................... SUCCESS [ 5.655 s]
[INFO] ASM (thirdparty) .................................. SUCCESS [ 2.353 s]
[INFO] Tajo RESTful Container ............................ SUCCESS [ 6.069 s]
[INFO] Tajo Metrics ...................................... SUCCESS [ 2.061 s]
[INFO] Tajo Core ......................................... SUCCESS [ 14.839 s]
[INFO] Tajo RPC .......................................... SUCCESS [ 0.950 s]
[INFO] Tajo Catalog Drivers Hive ......................... SUCCESS [ 43.017 s]
[INFO] Tajo Catalog Drivers .............................. SUCCESS [ 0.139 s]
[INFO] Tajo Catalog ...................................... SUCCESS [ 1.060 s]
[INFO] Tajo Client Example ............................... SUCCESS [ 1.217 s]
[INFO] Tajo HBase Storage ................................ SUCCESS [ 4.775 s]
[INFO] Tajo Cluster Tests ................................ SUCCESS [ 3.349 s]
[INFO] Tajo JDBC Driver .................................. FAILURE [ 44.527 s]
[INFO] Tajo JDBC storage common .......................... SKIPPED
[INFO] Tajo PostgreSQL JDBC storage ...................... SKIPPED
[INFO] Tajo Storage ...................................... SKIPPED
[INFO] Tajo Distribution ................................. SKIPPED
[INFO] Tajo Core Tests ................................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 08:45 min
[INFO] Finished at: 2015-11-10T09:38:55+00:00
[INFO] Final Memory: 149M/1692M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.19:test (default-test) on project tajo-jdbc: There are test failures.
[ERROR]
[ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-build/ws/tajo-jdbc/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-jdbc
Build step 'Execute shell' marked build as failure
Updating TAJO-1965
Jenkins build is back to normal : Tajo-master-build #975
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Tajo-master-build/975/changes>
Build failed in Jenkins: Tajo-master-build #974
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Tajo-master-build/974/changes>
Changes:
[jihoonson] TAJO-1975: Gathering fine-grained column statistics for range shuffle.
------------------------------------------
[...truncated 932 lines...]
Nov 13, 2015 4:40:29 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27919
Nov 13, 2015 4:40:34 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27919) shutdown
Nov 13, 2015 4:40:34 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27920
Nov 13, 2015 4:40:34 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27920
Nov 13, 2015 4:40:35 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27920
Nov 13, 2015 4:40:36 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27920
Nov 13, 2015 4:40:37 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27920
Nov 13, 2015 4:40:38 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27920
Nov 13, 2015 4:40:41 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27920) shutdown
Nov 13, 2015 4:40:41 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27921
Nov 13, 2015 4:40:45 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler userEventTriggered
INFO: Idle connection closed successfully :[id: 0x85fca440, /127.0.0.1:35521 :> /127.0.0.1:27921]
Nov 13, 2015 4:40:47 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27921) shutdown
Nov 13, 2015 4:40:47 AM org.apache.tajo.rpc.NettyClientBase doReconnect
WARNING: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:42051)]: ConnectException: Connection refused: /127.0.0.1:42051
Try to reconnect : /127.0.0.1:42051
Nov 13, 2015 4:40:48 AM org.apache.tajo.rpc.NettyClientBase doReconnect
SEVERE: Max retry count has been exceeded. attempts=2 caused by: java.net.ConnectException: Connection refused: /127.0.0.1:42051
Nov 13, 2015 4:40:48 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:42051
Nov 13, 2015 4:40:49 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:42051
Nov 13, 2015 4:40:50 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler exceptionCaught
SEVERE: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:42051)]: ClosedChannelException:
java.nio.channels.ClosedChannelException
Tests run: 16, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 71.874 sec - in org.apache.tajo.rpc.TestBlockingRpc
Running org.apache.tajo.rpc.TestRpcClientManager
Nov 13, 2015 4:40:52 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27922
Nov 13, 2015 4:40:55 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27922) shutdown
Nov 13, 2015 4:40:55 AM org.apache.tajo.rpc.RpcClientManager close
INFO: Closing RPC client manager
Nov 13, 2015 4:40:55 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27923
Nov 13, 2015 4:40:57 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27923) shutdown
Nov 13, 2015 4:40:57 AM org.apache.tajo.rpc.RpcClientManager close
INFO: Closing RPC client manager
Nov 13, 2015 4:40:57 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27924
Nov 13, 2015 4:40:57 AM org.apache.tajo.rpc.RpcClientManager close
INFO: Closing RPC client manager
Nov 13, 2015 4:40:59 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27924) shutdown
Nov 13, 2015 4:40:59 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27925
Nov 13, 2015 4:41:01 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27925) shutdown
Nov 13, 2015 4:41:01 AM org.apache.tajo.rpc.RpcClientManager close
INFO: Closing RPC client manager
Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 8.922 sec <<< FAILURE! - in org.apache.tajo.rpc.TestRpcClientManager
testClientCloseEventWithReconnect(org.apache.tajo.rpc.TestRpcClientManager) Time elapsed: 2.233 sec <<< FAILURE!
java.lang.AssertionError
at org.apache.tajo.rpc.TestRpcClientManager.testClientCloseEventWithReconnect(TestRpcClientManager.java:129)
Running org.apache.tajo.rpc.TestAsyncRpc
Nov 13, 2015 4:41:01 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27926
Nov 13, 2015 4:41:04 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27926) shutdown
Nov 13, 2015 4:41:04 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27927
Nov 13, 2015 4:41:05 AM org.apache.tajo.rpc.MonitorClientHandler userEventTriggered
INFO: Server has not respond [id: 0xa802fa32, /127.0.0.1:45534 => /127.0.0.1:27927]
Nov 13, 2015 4:41:05 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler exceptionCaught
SEVERE: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:27927)]:
Nov 13, 2015 4:41:16 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27927) shutdown
Nov 13, 2015 4:41:16 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27928
Nov 13, 2015 4:41:18 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27928) shutdown
Nov 13, 2015 4:41:18 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27929
Nov 13, 2015 4:41:18 AM org.apache.tajo.rpc.test.impl.DummyProtocolAsyncImpl getNull
INFO: noCallback is called
Nov 13, 2015 4:41:18 AM org.apache.tajo.rpc.TestAsyncRpc$4 run
INFO: testGetNull retrieved
Nov 13, 2015 4:41:20 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27929) shutdown
Nov 13, 2015 4:41:20 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27930
Nov 13, 2015 4:41:21 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler userEventTriggered
INFO: Idle connection closed successfully :[id: 0x4f660686, /127.0.0.1:53209 :> /127.0.0.1:27930]
Nov 13, 2015 4:41:21 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler userEventTriggered
INFO: Idle connection closed successfully :[id: 0x22230b6b, /127.0.0.1:53210 :> /127.0.0.1:27930]
Nov 13, 2015 4:41:24 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27930) shutdown
Nov 13, 2015 4:41:24 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27931
Nov 13, 2015 4:41:26 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27931) shutdown
Nov 13, 2015 4:41:26 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :localhost/127.0.0.1:27931
Nov 13, 2015 4:41:27 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler exceptionCaught
SEVERE: Exception [org.apache.tajo.rpc.test.DummyProtocol(localhost/127.0.0.1:27931)]: ClosedChannelException:
java.nio.channels.ClosedChannelException
Nov 13, 2015 4:41:27 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27932
Nov 13, 2015 4:41:29 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27932) shutdown
Nov 13, 2015 4:41:29 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :localhost/127.0.0.1:27932
Nov 13, 2015 4:41:30 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler exceptionCaught
SEVERE: Exception [org.apache.tajo.rpc.test.DummyProtocol(localhost/127.0.0.1:27932)]: ClosedChannelException:
java.nio.channels.ClosedChannelException
Nov 13, 2015 4:41:30 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27933
Nov 13, 2015 4:41:33 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27933) shutdown
Nov 13, 2015 4:41:33 AM org.apache.tajo.rpc.NettyClientBase doReconnect
WARNING: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:58255)]: ConnectException: Connection refused: /127.0.0.1:58255
Try to reconnect : /127.0.0.1:58255
Nov 13, 2015 4:41:34 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:58255
Nov 13, 2015 4:41:37 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:58255) shutdown
Nov 13, 2015 4:41:37 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27934
Nov 13, 2015 4:41:42 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27934) shutdown
Nov 13, 2015 4:41:42 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27935
Nov 13, 2015 4:41:47 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27935) shutdown
Nov 13, 2015 4:41:47 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27936
Nov 13, 2015 4:41:49 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27936) shutdown
Nov 13, 2015 4:41:49 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27937
Nov 13, 2015 4:41:52 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27937) shutdown
Nov 13, 2015 4:41:52 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27938
Nov 13, 2015 4:41:52 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27938
Nov 13, 2015 4:41:53 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27938
Nov 13, 2015 4:41:54 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27938
Nov 13, 2015 4:41:55 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27938
Nov 13, 2015 4:41:56 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:27938
Nov 13, 2015 4:41:59 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27938) shutdown
Nov 13, 2015 4:41:59 AM org.apache.tajo.rpc.NettyServerBase start
INFO: Rpc (DummyProtocol) listens on /127.0.0.1:27939
Nov 13, 2015 4:42:02 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler userEventTriggered
INFO: Idle connection closed successfully :[id: 0x3589609f, /127.0.0.1:54585 :> /127.0.0.1:27939]
Nov 13, 2015 4:42:04 AM org.apache.tajo.rpc.NettyServerBase shutdown
INFO: Rpc (DummyProtocol) listened on 127.0.0.1:27939) shutdown
Nov 13, 2015 4:42:04 AM org.apache.tajo.rpc.NettyClientBase doReconnect
WARNING: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:39408)]: ConnectException: Connection refused: /127.0.0.1:39408
Try to reconnect : /127.0.0.1:39408
Nov 13, 2015 4:42:05 AM org.apache.tajo.rpc.NettyClientBase doReconnect
SEVERE: Max retry count has been exceeded. attempts=2 caused by: java.net.ConnectException: Connection refused: /127.0.0.1:39408
Nov 13, 2015 4:42:05 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:39408
Nov 13, 2015 4:42:06 AM org.apache.tajo.rpc.NettyClientBase$1 operationComplete
WARNING: java.nio.channels.ClosedChannelException Try to reconnect :/127.0.0.1:39408
Nov 13, 2015 4:42:07 AM org.apache.tajo.rpc.NettyClientBase$NettyChannelInboundHandler exceptionCaught
SEVERE: Exception [org.apache.tajo.rpc.test.DummyProtocol(/127.0.0.1:39408)]: ClosedChannelException:
java.nio.channels.ClosedChannelException
Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 68.41 sec - in org.apache.tajo.rpc.TestAsyncRpc
Results :
Failed tests:
TestRpcClientManager.testClientCloseEventWithReconnect:129 null
Tests run: 37, Failures: 1, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [ 2.487 s]
[INFO] Tajo Project POM .................................. SUCCESS [ 2.240 s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [ 3.636 s]
[INFO] Tajo Common ....................................... SUCCESS [ 34.031 s]
[INFO] Tajo Algebra ...................................... SUCCESS [ 3.141 s]
[INFO] Tajo Catalog Common ............................... SUCCESS [ 5.740 s]
[INFO] Tajo Plan ......................................... SUCCESS [ 9.091 s]
[INFO] Tajo Rpc Common ................................... SUCCESS [ 1.413 s]
[INFO] Tajo Protocol Buffer Rpc .......................... FAILURE [02:31 min]
[INFO] Tajo Catalog Client ............................... SKIPPED
[INFO] Tajo Catalog Server ............................... SKIPPED
[INFO] Tajo Storage Common ............................... SKIPPED
[INFO] Tajo HDFS Storage ................................. SKIPPED
[INFO] Tajo PullServer ................................... SKIPPED
[INFO] Tajo Client ....................................... SKIPPED
[INFO] Tajo CLI tools .................................... SKIPPED
[INFO] Tajo SQL Parser ................................... SKIPPED
[INFO] ASM (thirdparty) .................................. SKIPPED
[INFO] Tajo RESTful Container ............................ SKIPPED
[INFO] Tajo Metrics ...................................... SKIPPED
[INFO] Tajo Core ......................................... SKIPPED
[INFO] Tajo RPC .......................................... SKIPPED
[INFO] Tajo Catalog Drivers Hive ......................... SKIPPED
[INFO] Tajo Catalog Drivers .............................. SKIPPED
[INFO] Tajo Catalog ...................................... SKIPPED
[INFO] Tajo Client Example ............................... SKIPPED
[INFO] Tajo HBase Storage ................................ SKIPPED
[INFO] Tajo Cluster Tests ................................ SKIPPED
[INFO] Tajo JDBC Driver .................................. SKIPPED
[INFO] Tajo JDBC storage common .......................... SKIPPED
[INFO] Tajo PostgreSQL JDBC storage ...................... SKIPPED
[INFO] Tajo Storage ...................................... SKIPPED
[INFO] Tajo Distribution ................................. SKIPPED
[INFO] Tajo Core Tests ................................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 03:34 min
[INFO] Finished at: 2015-11-13T04:42:10+00:00
[INFO] Final Memory: 73M/1395M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.19:test (default-test) on project tajo-rpc-protobuf: There are test failures.
[ERROR]
[ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-build/ws/tajo-rpc/tajo-rpc-protobuf/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-rpc-protobuf
Build step 'Execute shell' marked build as failure
Updating TAJO-1975