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-issues-unsubscr...@hadoop.apache.org For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org