Namit Maheshwari created HDDS-688:
-------------------------------------
Summary: Hive Query hangs, if DN's are restarted before the query
is submitted
Key: HDDS-688
URL: https://issues.apache.org/jira/browse/HDDS-688
Project: Hadoop Distributed Data Store
Issue Type: Bug
Reporter: Namit Maheshwari
Run a Hive Insert Query. It runs fine as below:
{code:java}
0: jdbc:hive2://ctr-e138-1518143905142-510793> insert into testo3 values(1,
"aa", 3.0);
INFO : Compiling
command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607):
insert into testo3 values(1, "aa", 3.0)
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_col0,
type:int, comment:null), FieldSchema(name:_col1, type:string, comment:null),
FieldSchema(name:_col2, type:float, comment:null)], properties:null)
INFO : Completed compiling
command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607); Time
taken: 0.52 seconds
INFO : Executing
command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607):
insert into testo3 values(1, "aa", 3.0)
INFO : Query ID = hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Subscribed to counters: [] for queryId:
hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607
INFO : Session is already open
INFO : Dag name: insert into testo3 values(1, "aa", 3.0) (Stage-1)
INFO : Status: Running (Executing on YARN cluster with App id
application_1539383731490_0073)
----------------------------------------------------------------------------------------------
VERTICES MODE STATUS TOTAL COMPLETED RUNNING PENDING FAILED KILLED
----------------------------------------------------------------------------------------------
Map 1 .......... container SUCCEEDED 1 1 0 0 0 0
Reducer 2 ...... container SUCCEEDED 1 1 0 0 0 0
----------------------------------------------------------------------------------------------
VERTICES: 02/02 [==========================>>] 100% ELAPSED TIME: 11.95 s
----------------------------------------------------------------------------------------------
INFO : Status: DAG finished successfully in 10.68 seconds
INFO :
INFO : Query Execution Summary
INFO :
----------------------------------------------------------------------------------------------
INFO : OPERATION DURATION
INFO :
----------------------------------------------------------------------------------------------
INFO : Compile Query 0.52s
INFO : Prepare Plan 0.23s
INFO : Get Query Coordinator (AM) 0.00s
INFO : Submit Plan 0.11s
INFO : Start DAG 0.57s
INFO : Run DAG 10.68s
INFO :
----------------------------------------------------------------------------------------------
INFO :
INFO : Task Execution Summary
INFO :
----------------------------------------------------------------------------------------------
INFO : VERTICES DURATION(ms) CPU_TIME(ms) GC_TIME(ms) INPUT_RECORDS
OUTPUT_RECORDS
INFO :
----------------------------------------------------------------------------------------------
INFO : Map 1 7074.00 11,280 276 3 1
INFO : Reducer 2 1074.00 2,040 0 1 0
INFO :
----------------------------------------------------------------------------------------------
INFO :
INFO : org.apache.tez.common.counters.DAGCounter:
INFO : NUM_SUCCEEDED_TASKS: 2
INFO : TOTAL_LAUNCHED_TASKS: 2
INFO : AM_CPU_MILLISECONDS: 1390
INFO : AM_GC_TIME_MILLIS: 0
INFO : File System Counters:
INFO : FILE_BYTES_READ: 135
INFO : FILE_BYTES_WRITTEN: 135
INFO : HDFS_BYTES_WRITTEN: 199
INFO : HDFS_READ_OPS: 3
INFO : HDFS_WRITE_OPS: 2
INFO : HDFS_OP_CREATE: 1
INFO : HDFS_OP_GET_FILE_STATUS: 3
INFO : HDFS_OP_RENAME: 1
INFO : org.apache.tez.common.counters.TaskCounter:
INFO : SPILLED_RECORDS: 0
INFO : NUM_SHUFFLED_INPUTS: 1
INFO : NUM_FAILED_SHUFFLE_INPUTS: 0
INFO : GC_TIME_MILLIS: 276
INFO : TASK_DURATION_MILLIS: 8474
INFO : CPU_MILLISECONDS: 13320
INFO : PHYSICAL_MEMORY_BYTES: 4294967296
INFO : VIRTUAL_MEMORY_BYTES: 11205029888
INFO : COMMITTED_HEAP_BYTES: 4294967296
INFO : INPUT_RECORDS_PROCESSED: 5
INFO : INPUT_SPLIT_LENGTH_BYTES: 1
INFO : OUTPUT_RECORDS: 1
INFO : OUTPUT_LARGE_RECORDS: 0
INFO : OUTPUT_BYTES: 94
INFO : OUTPUT_BYTES_WITH_OVERHEAD: 102
INFO : OUTPUT_BYTES_PHYSICAL: 127
INFO : ADDITIONAL_SPILLS_BYTES_WRITTEN: 0
INFO : ADDITIONAL_SPILLS_BYTES_READ: 0
INFO : ADDITIONAL_SPILL_COUNT: 0
INFO : SHUFFLE_BYTES: 103
INFO : SHUFFLE_BYTES_DECOMPRESSED: 102
INFO : SHUFFLE_BYTES_TO_MEM: 0
INFO : SHUFFLE_BYTES_TO_DISK: 0
INFO : SHUFFLE_BYTES_DISK_DIRECT: 103
INFO : SHUFFLE_PHASE_TIME: 154
INFO : FIRST_EVENT_RECEIVED: 108
INFO : LAST_EVENT_RECEIVED: 108
INFO : HIVE:
INFO : CREATED_FILES: 2
INFO : DESERIALIZE_ERRORS: 0
INFO : RECORDS_IN_Map_1: 3
INFO : RECORDS_OUT_0: 1
INFO : RECORDS_OUT_1_default.testo3: 1
INFO : RECORDS_OUT_INTERMEDIATE_Map_1: 1
INFO : RECORDS_OUT_INTERMEDIATE_Reducer_2: 0
INFO : RECORDS_OUT_OPERATOR_FS_12: 1
INFO : RECORDS_OUT_OPERATOR_FS_5: 1
INFO : RECORDS_OUT_OPERATOR_GBY_10: 1
INFO : RECORDS_OUT_OPERATOR_GBY_8: 1
INFO : RECORDS_OUT_OPERATOR_MAP_0: 0
INFO : RECORDS_OUT_OPERATOR_RS_9: 1
INFO : RECORDS_OUT_OPERATOR_SEL_1: 1
INFO : RECORDS_OUT_OPERATOR_SEL_3: 1
INFO : RECORDS_OUT_OPERATOR_SEL_7: 1
INFO : RECORDS_OUT_OPERATOR_TS_0: 1
INFO : RECORDS_OUT_OPERATOR_UDTF_2: 1
INFO : TaskCounter_Map_1_INPUT__dummy_table:
INFO : INPUT_RECORDS_PROCESSED: 4
INFO : INPUT_SPLIT_LENGTH_BYTES: 1
INFO : TaskCounter_Map_1_OUTPUT_Reducer_2:
INFO : ADDITIONAL_SPILLS_BYTES_READ: 0
INFO : ADDITIONAL_SPILLS_BYTES_WRITTEN: 0
INFO : ADDITIONAL_SPILL_COUNT: 0
INFO : OUTPUT_BYTES: 94
INFO : OUTPUT_BYTES_PHYSICAL: 127
INFO : OUTPUT_BYTES_WITH_OVERHEAD: 102
INFO : OUTPUT_LARGE_RECORDS: 0
INFO : OUTPUT_RECORDS: 1
INFO : SPILLED_RECORDS: 0
INFO : TaskCounter_Reducer_2_INPUT_Map_1:
INFO : FIRST_EVENT_RECEIVED: 108
INFO : INPUT_RECORDS_PROCESSED: 1
INFO : LAST_EVENT_RECEIVED: 108
INFO : NUM_FAILED_SHUFFLE_INPUTS: 0
INFO : NUM_SHUFFLED_INPUTS: 1
INFO : SHUFFLE_BYTES: 103
INFO : SHUFFLE_BYTES_DECOMPRESSED: 102
INFO : SHUFFLE_BYTES_DISK_DIRECT: 103
INFO : SHUFFLE_BYTES_TO_DISK: 0
INFO : SHUFFLE_BYTES_TO_MEM: 0
INFO : SHUFFLE_PHASE_TIME: 154
INFO : TaskCounter_Reducer_2_OUTPUT_out_Reducer_2:
INFO : OUTPUT_RECORDS: 0
INFO : Starting task [Stage-2:DEPENDENCY_COLLECTION] in serial mode
INFO : Starting task [Stage-0:MOVE] in serial mode
INFO : Loading data to table default.testo3 from
o3fs://bucket2.volume2/testo3/.hive-staging_hive_2018-10-18_00-57-29_750_2488867853984287387-1/-ext-10000
INFO : Starting task [Stage-3:STATS] in serial mode
INFO : Completed executing
command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607); Time
taken: 12.797 seconds
INFO : OK
No rows affected (13.366 seconds)
0: jdbc:hive2://ctr-e138-1518143905142-510793> select * from testo3;
INFO : Compiling
command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4):
select * from testo3
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:testo3.i,
type:int, comment:null), FieldSchema(name:testo3.s, type:string, comment:null),
FieldSchema(name:testo3.d, type:float, comment:null)], properties:null)
INFO : Completed compiling
command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4); Time
taken: 0.244 seconds
INFO : Executing
command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4):
select * from testo3
INFO : Completed executing
command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4); Time
taken: 0.013 seconds
INFO : OK
+--------------+--------------+--------------+
| testo3.i | testo3.s | testo3.d |
+--------------+--------------+--------------+
| 2 | aa | 3.0 |
| 2 | aa | 3.0 |
| 1 | aa | 3.0 |
+--------------+--------------+--------------+
3 rows selected (0.404 seconds)
{code}
Now shutdown the DN's on all the hosts.
Wait for three minutes. Start the DN's back. And submit the insert query again.
It hangs forever:
{code:java}
0: jdbc:hive2://ctr-e138-1518143905142-510793> insert into testo3 values(5,
"aa", 3.0);
INFO : Compiling
command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892):
insert into testo3 values(5, "aa", 3.0)
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_col0,
type:int, comment:null), FieldSchema(name:_col1, type:string, comment:null),
FieldSchema(name:_col2, type:float, comment:null)], properties:null)
INFO : Completed compiling
command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892); Time
taken: 0.67 seconds
INFO : Executing
command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892):
insert into testo3 values(5, "aa", 3.0)
INFO : Query ID = hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Subscribed to counters: [] for queryId:
hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892
INFO : Session is already open
INFO : Dag name: insert into testo3 values(5, "aa", 3.0) (Stage-1)
INFO : Tez session was closed. Reopening...
INFO : Session re-established.
INFO : Session re-established.
INFO : Status: Running (Executing on YARN cluster with App id
application_1539383731490_0074)
----------------------------------------------------------------------------------------------
VERTICES MODE STATUS TOTAL COMPLETED RUNNING PENDING FAILED KILLED
----------------------------------------------------------------------------------------------
Map 1 container RUNNING 1 0 1 0 0 0
Reducer 2 container INITED 1 0 0 1 0 0
----------------------------------------------------------------------------------------------
VERTICES: 00/02 [>>--------------------------] 0% ELAPSED TIME: 879.84 s
----------------------------------------------------------------------------------------------
{code}
SCM logs:
{code:java}
2018-10-18 01:05:11,589 INFO
org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher:
RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251724 timed
out. Retrying. 2018-10-18 01:06:09,757 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline
pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:06:09,757 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Finalizing pipeline.
pipelineID: pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 2018-10-18
01:06:09,757 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 6 2018-10-18 01:06:09,758 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 8 2018-10-18 01:06:09,759 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 10 2018-10-18 01:06:09,759 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 12 2018-10-18 01:06:09,760 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 14 2018-10-18 01:06:09,761 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 16 2018-10-18 01:06:09,761 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 1 2018-10-18 01:06:09,762 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 18 2018-10-18 01:06:09,762 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 4 2018-10-18 01:06:09,762 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 20 2018-10-18 01:06:11,591 INFO
org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher:
RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251725 timed
out. Retrying. 2018-10-18 01:06:12,757 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline
pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:06:12,757 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline
pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:07:11,593 INFO
org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher:
RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251726 timed
out. Retrying. 2018-10-18 01:08:11,596 INFO
org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher:
RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251727 timed
out. Retrying. 2018-10-18 01:09:41,597 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 77e36898-91b2-4a81-92ec-a285781b5235 for containerID 3.
Datanode delete txnID: 0, SCM txnID: 1 2018-10-18 01:09:43,500 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,501 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,502 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,502 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,502 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,502 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:43,502 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found
2018-10-18 01:09:48,073 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Closing pipeline.
pipelineID: pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 2018-10-18
01:10:11,608 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService:
Totally added 6 delete blocks command for 3 datanodes, task elapsed time: 2ms
2018-10-18 01:10:13,652 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,652 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,652 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,652 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,653 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,653 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:13,653 WARN
org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit
by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed.
Corresponding entry not found. 2018-10-18 01:10:19,824 WARN
org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without
active lease. Id=4 2018-10-18 01:10:19,824 WARN
org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without
active lease. Id=6 2018-10-18 01:10:19,824 WARN
org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without
active lease. Id=8 2018-10-18 01:10:19,824 WARN
org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without
active lease. Id=10 2018-10-18 01:10:52,281 INFO
org.apache.hadoop.hdds.scm.pipelines.ratis.RatisManagerImpl: Allocating a new
ratis pipeline of size: 3 id: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560
2018-10-18 01:10:52,390 INFO
org.apache.hadoop.hdds.scm.pipelines.ratis.RatisManagerImpl: Allocating a new
ratis pipeline of size: 3 id: pipelineId=7c393f6d-2c31-448d-9f40-0eb4f0c628b4
2018-10-18 01:11:43,494 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 120899ms
2018-10-18 01:11:58,403 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 120187ms
2018-10-18 01:12:13,486 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 129851ms
2018-10-18 01:12:18,792 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline
pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560. 2018-10-18 01:12:18,793 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Finalizing pipeline.
pipelineID: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 2018-10-18
01:12:18,793 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 38 2018-10-18 01:12:18,794 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 24 2018-10-18 01:12:18,794 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 40 2018-10-18 01:12:18,794 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 26 2018-10-18 01:12:18,795 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 28 2018-10-18 01:12:18,795 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 30 2018-10-18 01:12:18,795 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 32 2018-10-18 01:12:18,795 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 34 2018-10-18 01:12:18,796 INFO
org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close
container Event triggered for container : 36 2018-10-18 01:12:21,793 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline
pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560. 2018-10-18 01:12:28,399 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 129066ms
2018-10-18 01:12:43,483 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 160331ms
2018-10-18 01:12:58,398 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 158856ms
2018-10-18 01:13:13,481 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 190378ms
2018-10-18 01:13:18,877 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Closing pipeline.
pipelineID: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 2018-10-18
01:13:28,406 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 189518ms
2018-10-18 01:13:28,407 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 121129ms
2018-10-18 01:13:43,479 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 219451ms
2018-10-18 01:13:58,399 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 219784ms
2018-10-18 01:14:13,476 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 249410ms
2018-10-18 01:14:28,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 249460ms
2018-10-18 01:14:43,497 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 279759ms
2018-10-18 01:14:58,403 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 279756ms
2018-10-18 01:15:13,473 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 310306ms
2018-10-18 01:15:28,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 308983ms
2018-10-18 01:15:43,481 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 339323ms
2018-10-18 01:15:58,399 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 339037ms
2018-10-18 01:16:13,486 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 369335ms
2018-10-18 01:16:28,409 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 368800ms
2018-10-18 01:16:43,489 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 400142ms
2018-10-18 01:16:58,400 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 399306ms
2018-10-18 01:17:13,496 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 429758ms
2018-10-18 01:17:28,399 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 429533ms
2018-10-18 01:17:43,495 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 460167ms
2018-10-18 01:17:58,399 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 459247ms
2018-10-18 01:18:13,495 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 490224ms
2018-10-18 01:18:28,403 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 489329ms
2018-10-18 01:18:43,500 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 519788ms
2018-10-18 01:18:58,400 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 519200ms
2018-10-18 01:19:13,499 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 550393ms
2018-10-18 01:19:28,404 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 549081ms
2018-10-18 01:19:43,501 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 579560ms
2018-10-18 01:19:58,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 579204ms
2018-10-18 01:20:13,499 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 610467ms
2018-10-18 01:20:28,400 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 609169ms
2018-10-18 01:20:43,498 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 639947ms
2018-10-18 01:20:48,819 INFO org.apache.hadoop.hdds.scm.node.DeadNodeHandler:
Datanode 41636d6e-31cc-419b-bd8d-1a7e5e7d7edd is dead. Removing replications
from the in-memory state. 2018-10-18 01:20:51,819 INFO
org.apache.hadoop.hdds.scm.node.DeadNodeHandler: Datanode
69d15283-4e2e-4c30-a028-f2bad0f83cc1 is dead. Removing replications from the
in-memory state. 2018-10-18 01:20:58,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 639148ms
2018-10-18 01:21:13,498 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 670081ms
2018-10-18 01:21:27,978 WARN org.apache.hadoop.hdds.server.events.EventQueue:
No event handler registered for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:28,402 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 669044ms
2018-10-18 01:21:28,594 WARN org.apache.hadoop.hdds.server.events.EventQueue:
No event handler registered for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:28,594 WARN
org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered
for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:28,594 WARN
org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered
for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:43,498 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 700237ms
2018-10-18 01:21:43,498 WARN org.apache.hadoop.hdds.server.events.EventQueue:
No event handler registered for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:43,498 WARN
org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered
for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:44,737 WARN
org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered
for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:46,602 WARN
org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered
for event TypedEvent{payloadType=ReplicationStatus,
name='Replicate_Command_Status'} 2018-10-18 01:21:46,603 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:21:57,972 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6.
Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:21:58,404 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 699691ms
2018-10-18 01:21:58,589 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:22:13,500 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 729913ms
2018-10-18 01:22:28,403 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 729239ms
^[[B^[[B^[[A2018-10-18 01:22:43,501 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 760211ms
2018-10-18 01:22:44,733 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 93a33804-d0b9-4adf-b39b-e1c190be9c32 for containerID 6.
Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:22:58,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 758951ms
2018-10-18 01:22:58,585 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:23:13,503 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 790104ms
2018-10-18 01:23:16,600 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:23:28,032 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6.
Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:23:28,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 789426ms
2018-10-18 01:23:43,506 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 819373ms
2018-10-18 01:23:58,401 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 819308ms
2018-10-18 01:24:13,512 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 850302ms
2018-10-18 01:24:28,400 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 849243ms
2018-10-18 01:24:28,579 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:24:43,513 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 879865ms
2018-10-18 01:24:44,734 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 93a33804-d0b9-4adf-b39b-e1c190be9c32 for containerID 6.
Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:24:46,604 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10.
Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:24:57,978 INFO
org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID
mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6.
Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:24:58,400 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for
reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 879492ms
2018-10-18 01:25:13,517 INFO
org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing
pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for
reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for
910432ms{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-dev-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-dev-h...@hadoop.apache.org
