[ https://issues.apache.org/jira/browse/HBASE-14820?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15009219#comment-15009219 ]
Clara Xiong commented on HBASE-14820: ------------------------------------- 2015-11-16 07:26:43,434 DEBUG [MemStoreFlusher.1] regionserver.CompactSplitThread: Split requested for [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q \xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a.. compaction_queue=(0:0), split_queue=0, merge_queue=0 2015-11-16 07:26:43,788 DEBUG [regionserver60020-splits-1447687603434] lock.ZKInterProcessLockBase: Acquired a lock for /hbase/table-lock/[TableName]/read-regionserver:600200000009873 2015-11-16 07:26:43,789 INFO [regionserver60020-splits-1447687603434] regionserver.SplitTransaction: Starting split of region [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB 5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. 2015-11-16 07:26:43,789 DEBUG [regionserver60020-splits-1447687603434] regionserver.SplitTransaction: regionserver:60020-0x1503f523d9f032a, quorum=hm4.[Host]:2181,hm3.[Host]: 2181,hm2.[Host]:2181,hm1.[Host]:2181,hm5.[Host]:2181, baseZNode=/hbase Creating ephemeral node for 4c467284476f9627dd8e7a4f34dfd31a in PENDING_SPLIT state 2015-11-16 07:26:43,790 DEBUG [regionserver60020-splits-1447687603434] regionserver.SplitTransaction: Still waiting for master to process the pending_split for 4c467284476f9627dd8e7a4f34dfd31a 2015-11-16 07:26:43,790 DEBUG [regionserver60020-splits-1447687603434] zookeeper.ZKAssign: regionserver:60020-0x1503f523d9f032a, quorum=hm4.[Host]:2181,hm3.[Host]:2181,hm2.[Host][Host]:2181,hm1.[Host]:2181,hm5.[Host]:2181, baseZNode=/hbase Transitioning 4c467284476f9627dd8e7a4f34dfd31a from RS_ZK_REQUEST_REGION_SPLIT to RS_ZK_REQUEST_REGI ON_SPLIT 2015-11-16 07:26:43,791 DEBUG [regionserver60020-splits-1447687603434] zookeeper.ZKAssign: regionserver:60020-0x1503f523d9f032a, quorum=hm4.[Host]:2181,hm3.[Host]:2181,hm2.[Host]:2181,hm1.[Host]:2181,hm5.[Host]:2181, baseZNode=/hbase Transitioned node 4c467284476f9627dd8e7a4f34dfd31a from RS_ZK_REQUEST_REGION_SPLIT to RS_ZK_REQUEST_ REGION_SPLIT 2015-11-16 07:26:43,986 DEBUG [regionserver60020-splits-1447687603434] regionserver.HRegion: Closing [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\x CB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a.: disabling compactions & flushes 2015-11-16 07:26:43,986 DEBUG [regionserver60020-splits-1447687603434] regionserver.HRegion: Updates disabled for region [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\ x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. 2015-11-16 07:26:43,986 INFO [regionserver60020-splits-1447687603434] regionserver.HRegion: Started memstore flush for [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x 16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a., current region memstore size 363.0 K 2015-11-16 07:26:44,527 INFO [regionserver60020-splits-1447687603434] regionserver.DefaultStoreFlusher: Flushed, sequenceid=12742653, memsize=363.0 K, hasBloomFilter=false, into tmp file hdfs://hm1.[Host]]:9000/hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a/.tmp/fe0ca3b83b794cef8c1cb357ccc08db6 2015-11-16 07:26:44,532 DEBUG [regionserver60020-splits-1447687603434] regionserver.HRegionFileSystem: Committing store file hdfs://hm1.[Host]:9000/hbase/data/default/[TableName]/4c4672844 76f9627dd8e7a4f34dfd31a/.tmp/fe0ca3b83b794cef8c1cb357ccc08db6 as hdfs://hm1.[Host]:9000/hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a/e/fe0ca3b83b794cef8c1cb357ccc08db6 2015-11-16 07:26:44,536 INFO [regionserver60020-splits-1447687603434] regionserver.HStore: Added hdfs://hm1.[Host]:9000/hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a/e/f e0ca3b83b794cef8c1cb357ccc08db6, entries=368, sequenceid=12742653, filesize=82.7 K 2015-11-16 07:26:44,536 INFO [regionserver60020-splits-1447687603434] regionserver.HRegion: Finished memstore flush of ~363.0 K/371744, currentsize=0/0 for region [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. in 550ms, sequenceid=12742653, compaction requested=false 2015-11-16 07:26:44,672 INFO [StoreCloserThread-[TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f3 4dfd31a.-1] regionserver.HStore: Closed e 2015-11-16 07:26:44,673 INFO [regionserver60020-splits-1447687603434] regionserver.HRegion: Closed [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xC B!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. 2015-11-16 07:26:44,673 INFO [regionserver60020-splits-1447687603434] regionserver.SplitTransaction: Preparing to split 1 storefiles for region [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15' \xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. 2015-11-16 07:27:14,725 INFO [regionserver60020-splits-1447687603434] regionserver.SplitRequest: Running rollback/cleanup of failed split of [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD 7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a.; Took too long to split the files and create the references, aborting split java.io.IOException: Took too long to split the files and create the references, aborting split at org.apache.hadoop.hbase.regionserver.SplitTransaction.splitStoreFiles(SplitTransaction.java:855) at org.apache.hadoop.hbase.regionserver.SplitTransaction.stepsBeforePONR(SplitTransaction.java:433) at org.apache.hadoop.hbase.regionserver.SplitTransaction.createDaughters(SplitTransaction.java:307) at org.apache.hadoop.hbase.regionserver.SplitTransaction.execute(SplitTransaction.java:676) at org.apache.hadoop.hbase.regionserver.SplitRequest.run(SplitRequest.java:85) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2015-11-16 07:27:14,823 DEBUG [regionserver60020-splits-1447687603434] regionserver.HRegion: Found 0 recovered edits file(s) under hdfs://hm1.[Host]:9000/hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a 2015-11-16 07:27:14,824 WARN [regionserver60020-splits-1447687603434] zookeeper.ZKAssign: regionserver:60020-0x1503f523d9f032a, quorum=hm4.[Host]:2181,hm3.[Host]:2181,hm2.[Host]:2181,hm1.[Host]:2181,hm5.[Host]:2181, baseZNode=/hbase Attempting to delete unassigned node 4c467284476f9627dd8e7a4f34dfd31a in RS_ZK_REQUEST_REGION_SPLIT state but node is in RS_ZK_REGION_SPLITTING state 2015-11-16 07:27:14,825 DEBUG [regionserver60020-splits-1447687603434] zookeeper.ZKAssign: regionserver:60020-0x1503f523d9f032a, quorum=hm4.[Host]:2181,hm3.[Host]:2181,hm2.[Host]:2181,hm1.[Host]:2181,hm5.[Host]:2181, baseZNode=/hbase Deleted unassigned node 4c467284476f9627dd8e7a4f34dfd31a in expected state RS_ZK_REGION_SPLITTING 2015-11-16 07:27:14,825 INFO [regionserver60020-splits-1447687603434] regionserver.SplitRequest: Successful rollback of failed split of [TableName],\x85\xDF`\x7F\xFF\xFE\xCE ,\xB6{\xD0\xA5\x15'\xD7\xD6g\x8E_k\xB5\x13\x16g%\x9D\x06\xC5q\xCB!\xBFI\x01,1447477545041.4c467284476f9627dd8e7a4f34dfd31a. 2015-11-16 07:27:14,827 DEBUG [regionserver60020-splits-1447687603434] lock.ZKInterProcessLockBase: Released /hbase/table-lock/[TableName]/read-regionserver:600200000009873 2015-11-16 07:27:14,827 INFO [regionserver60020-splits-1447687603434] regionserver.SplitRequest: Split transaction journal: STARTED at 1447687603661 PREPARED at 1447687603788 BEFORE_PRE_SPLIT_HOOK at 1447687603789 AFTER_PRE_SPLIT_HOOK at 1447687603789 SET_SPLITTING_IN_ZK at 1447687603790 CREATE_SPLIT_DIR at 1447687603986 CLOSED_PARENT_REGION at 1447687604673 OFFLINED_PARENT at 1447687604673 2015-11-16 07:28:05,959 INFO [Thread-20670827] hdfs.DFSClient: Exception in createBlockOutputStream java.net.SocketTimeoutException: 75000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/10.249.198.246:45824 remote=/10.249.198.246:50010] at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164) at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161) at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131) at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:118) at java.io.FilterInputStream.read(FilterInputStream.java:83) at java.io.FilterInputStream.read(FilterInputStream.java:83) at org.apache.hadoop.hdfs.protocolPB.PBHelper.vintPrefixed(PBHelper.java:2201) at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.createBlockOutputStream(DFSOutputStream.java:1439) at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.nextBlockOutputStream(DFSOutputStream.java:1361) at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:588) 2015-11-16 07:28:05,959 INFO [Thread-20670827] hdfs.DFSClient: Abandoning BP-17464394-10.249.192.41-1437430130467:blk_1203771348_130031565 2015-11-16 07:28:06,517 WARN [Thread-20670827] hdfs.DFSClient: DataStreamer Exception org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException): No lease on /hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a/.splits/f0f72e76c9079476df6cf16a57086beb/e/b866441ce0284a6b9e794270ae861359.4c467284476f9627dd8e7a4f34dfd31a (inode 153365501): File does not exist. [Lease. Holder: DFSClient_hb_rs_hs1526.[Host],60020,1445544584894_1032217520_45, pendingcreates: 1] at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:3549) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.abandonBlock(FSNamesystem.java:3519) at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.abandonBlock(NameNodeRpcServer.java:709) at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.abandonBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:467) at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java) at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:619) at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:962) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2096) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2092) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:422) at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1694) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2090) at org.apache.hadoop.ipc.Client.call(Client.java:1468) at org.apache.hadoop.ipc.Client.call(Client.java:1399) at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:232) at com.sun.proxy.$Proxy16.abandonBlock(Unknown Source) at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolTranslatorPB.abandonBlock(ClientNamenodeProtocolTranslatorPB.java:376) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:187) at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:102) at com.sun.proxy.$Proxy17.abandonBlock(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.apache.hadoop.hbase.fs.HFileSystem$1.invoke(HFileSystem.java:294) at com.sun.proxy.$Proxy18.abandonBlock(Unknown Source) at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.nextBlockOutputStream(DFSOutputStream.java:1365) at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:588) 2015-11-16 07:28:06,517 WARN [Thread-20670827] hdfs.DFSClient: Could not get block locations. Source file "/hbase/data/default/[TableName]/4c467284476f9627dd8e7a4f34dfd31a/.splits/f0f72e76c9079476df6cf16a57086beb/e/b866441ce0284a6b9e794270ae861359.4c467284476f9627dd8e7a4f34dfd31a" - Aborting... 2015-11-16 09:58:02,031 WARN [regionserver60020-smallCompactions-1447694140073] hdfs.BlockReaderFactory: I/O error constructing remote block reader. java.io.IOException: Got error for OP_READ_BLOCK, self=/10.249.198.246:18432, remote=/10.249.194.239:50010, for file /hbase/data/default/[TableName]/da91c5a2ddf7ac8350a0555961fa793c/e/c245ebf9c399492ea6 0eef9fba98a52b, for pool BP-17464394-10.249.192.41-1437430130467 block 1203905906_130166129 at org.apache.hadoop.hdfs.RemoteBlockReader2.checkSuccess(RemoteBlockReader2.java:445) at org.apache.hadoop.hdfs.RemoteBlockReader2.newBlockReader(RemoteBlockReader2.java:410) at org.apache.hadoop.hdfs.BlockReaderFactory.getRemoteBlockReader(BlockReaderFactory.java:796) at org.apache.hadoop.hdfs.BlockReaderFactory.getRemoteBlockReaderFromTcp(BlockReaderFactory.java:674) at org.apache.hadoop.hdfs.BlockReaderFactory.build(BlockReaderFactory.java:337) at org.apache.hadoop.hdfs.DFSInputStream.blockSeekTo(DFSInputStream.java:576) at org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy(DFSInputStream.java:800) at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:847) at java.io.DataInputStream.read(DataInputStream.java:149) at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:192) at org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1312) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockDataInternal(HFileBlock.java:1581) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockData(HFileBlock.java:1413) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:394) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:810) at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:244) at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:152) at org.apache.hadoop.hbase.regionserver.StoreScanner.seekScanners(StoreScanner.java:329) at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:252) at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:214) at org.apache.hadoop.hbase.regionserver.compactions.Compactor.createScanner(Compactor.java:299) at org.apache.hadoop.hbase.regionserver.compactions.DefaultCompactor.compact(DefaultCompactor.java:87) at org.apache.hadoop.hbase.regionserver.DefaultStoreEngine$DefaultCompactionContext.compact(DefaultStoreEngine.java:112) at org.apache.hadoop.hbase.regionserver.HStore.compact(HStore.java:1113) at org.apache.hadoop.hbase.regionserver.HRegion.compact(HRegion.java:1526) at org.apache.hadoop.hbase.regionserver.CompactSplitThread$CompactionRunner.run(CompactSplitThread.java:498) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) > Region becomes unavailable after a region split is rolled back > -------------------------------------------------------------- > > Key: HBASE-14820 > URL: https://issues.apache.org/jira/browse/HBASE-14820 > Project: HBase > Issue Type: Bug > Components: master, regionserver > Affects Versions: 0.98.15 > Reporter: Clara Xiong > > After the region server rolls back a timed out attempt of region split, the > region becomes unavailable. > Symptoms: > The RS displays the region open in the web UI. > The meta table still points to the RS > Requests for the regions receive a NotServingRegionException. > hbck reports 0 inconsistencies. > Moving the region fails. > Restarting the region server fixes the problem. > We have see multiple occurrences which require operation intervention. -- This message was sent by Atlassian JIRA (v6.3.4#6332)