stack created HBASE-19701:
-----------------------------
Summary: Close without justification following succesful open
Key: HBASE-19701
URL: https://issues.apache.org/jira/browse/HBASE-19701
Project: HBase
Issue Type: Bug
Reporter: stack
Priority: Critical
Fix For: 2.0.0-beta-2
[~jmspaggi] conjured an interesting condition where we close a region soon
after open WITHOUT seemingly saying why (It looks like Master is asking for
region CLOSE but that is not clear looking at RegionServer log).
Here is log snippet from https://pastebin.com/0r76Y6ap (in case the pastebin
evaporates)
{code}
....
2017-12-31 09:54:20,864 INFO
[PostOpenDeployTasks:f49f3cbb7f3db4cf96c7eb3b0cf83869]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000408944640,1505391191559.f49f3cbb7f3db4cf96c7eb3b0cf83869.
2017-12-31 09:54:20,870 INFO [StoreOpener-330f09f4a0eaf26811c320fbf1b14e70-1]
regionserver.CompactingMemStore: Setting in-memory flush size threshold to
13421772 and immutable segments index to be of type CHUNK_MAP
2017-12-31 09:54:20,870 INFO [StoreOpener-330f09f4a0eaf26811c320fbf1b14e70-1]
regionserver.HStore: Memstore class name is
org.apache.hadoop.hbase.regionserver.CompactingMemStore
2017-12-31 09:54:20,870 INFO [StoreOpener-330f09f4a0eaf26811c320fbf1b14e70-1]
hfile.CacheConfig: Created cacheConfig for info:
blockCache=LruBlockCache{blockCount=0, currentSize=2454760,
freeSize=3347745560, maxSize=3350200320, heapSize=2454760, minSize=3182690304,
minFactor=0.95, multiSize=1591345152, multiFactor=0.5, singleSize=795672576,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2017-12-31 09:54:20,872 INFO [StoreOpener-330f09f4a0eaf26811c320fbf1b14e70-1]
compactions.CompactionConfiguration: size [134217728, 9223372036854775807,
9223372036854775807); files [3, 10); ratio 1,200000; off-peak ratio 5,000000;
throttle point 2684354560; major period 604800000, major jitter 0,500000, min
locality to compact 0,000000; tiered compaction: max_age 9223372036854775807,
incoming window min 6, compaction policy for tiered window
org.apache.hadoop.hbase.regionserver.compactions.ExploringCompactionPolicy,
single output for minor true, compaction window factory
org.apache.hadoop.hbase.regionserver.compactions.ExponentialCompactionWindowFactory
2017-12-31 09:54:20,903 INFO [StoreOpener-166b9c45d7724f72fd126adb4445d6ec-1]
regionserver.CompactingMemStore: Setting in-memory flush size threshold to
13421772 and immutable segments index to be of type CHUNK_MAP
2017-12-31 09:54:20,904 INFO [StoreOpener-166b9c45d7724f72fd126adb4445d6ec-1]
regionserver.HStore: Memstore class name is
org.apache.hadoop.hbase.regionserver.CompactingMemStore
2017-12-31 09:54:20,904 INFO [StoreOpener-166b9c45d7724f72fd126adb4445d6ec-1]
hfile.CacheConfig: Created cacheConfig for info:
blockCache=LruBlockCache{blockCount=0, currentSize=2454760,
freeSize=3347745560, maxSize=3350200320, heapSize=2454760, minSize=3182690304,
minFactor=0.95, multiSize=1591345152, multiFactor=0.5, singleSize=795672576,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2017-12-31 09:54:20,905 INFO [StoreOpener-166b9c45d7724f72fd126adb4445d6ec-1]
compactions.CompactionConfiguration: size [134217728, 9223372036854775807,
9223372036854775807); files [3, 10); ratio 1,200000; off-peak ratio 5,000000;
throttle point 2684354560; major period 604800000, major jitter 0,500000, min
locality to compact 0,000000; tiered compaction: max_age 9223372036854775807,
incoming window min 6, compaction policy for tiered window
org.apache.hadoop.hbase.regionserver.compactions.ExploringCompactionPolicy,
single output for minor true, compaction window factory
org.apache.hadoop.hbase.regionserver.compactions.ExponentialCompactionWindowFactory
2017-12-31 09:54:20,929 INFO [RS_OPEN_REGION-node1:16020-1]
regionserver.HRegion: Setting FlushNonSloppyStoresFirstPolicy for the
region=TestTable,00000000000000000262144000,1505391191559.166b9c45d7724f72fd126adb4445d6ec.
2017-12-31 09:54:20,956 INFO [RS_OPEN_REGION-node1:16020-0]
regionserver.HRegion: Setting FlushNonSloppyStoresFirstPolicy for the
region=TestTable,00000000000000000188743680,1505391191559.330f09f4a0eaf26811c320fbf1b14e70.
2017-12-31 09:54:20,991 INFO [RS_OPEN_REGION-node1:16020-1]
regionserver.HRegion: Onlined 166b9c45d7724f72fd126adb4445d6ec; next
sequenceid=22861
2017-12-31 09:54:20,998 INFO
[PostOpenDeployTasks:166b9c45d7724f72fd126adb4445d6ec]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000262144000,1505391191559.166b9c45d7724f72fd126adb4445d6ec.
2017-12-31 09:54:21,025 INFO [RS_OPEN_REGION-node1:16020-0]
regionserver.HRegion: Onlined 330f09f4a0eaf26811c320fbf1b14e70; next
sequenceid=21870
2017-12-31 09:54:21,031 INFO
[PostOpenDeployTasks:330f09f4a0eaf26811c320fbf1b14e70]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000188743680,1505391191559.330f09f4a0eaf26811c320fbf1b14e70.
2017-12-31 09:54:21,036 INFO [StoreOpener-ba17cd27e2822b91193359a273684ac2-1]
regionserver.CompactingMemStore: Setting in-memory flush size threshold to
13421772 and immutable segments index to be of type CHUNK_MAP
2017-12-31 09:54:21,036 INFO [StoreOpener-ba17cd27e2822b91193359a273684ac2-1]
regionserver.HStore: Memstore class name is
org.apache.hadoop.hbase.regionserver.CompactingMemStore
2017-12-31 09:54:21,036 INFO [StoreOpener-ba17cd27e2822b91193359a273684ac2-1]
hfile.CacheConfig: Created cacheConfig for info:
blockCache=LruBlockCache{blockCount=0, currentSize=2454760,
freeSize=3347745560, maxSize=3350200320, heapSize=2454760, minSize=3182690304,
minFactor=0.95, multiSize=1591345152, multiFactor=0.5, singleSize=795672576,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2017-12-31 09:54:21,037 INFO [StoreOpener-ba17cd27e2822b91193359a273684ac2-1]
compactions.CompactionConfiguration: size [134217728, 9223372036854775807,
9223372036854775807); files [3, 10); ratio 1,200000; off-peak ratio 5,000000;
throttle point 2684354560; major period 604800000, major jitter 0,500000, min
locality to compact 0,000000; tiered compaction: max_age 9223372036854775807,
incoming window min 6, compaction policy for tiered window
org.apache.hadoop.hbase.regionserver.compactions.ExploringCompactionPolicy,
single output for minor true, compaction window factory
org.apache.hadoop.hbase.regionserver.compactions.ExponentialCompactionWindowFactory
2017-12-31 09:54:21,058 INFO [StoreOpener-e6ad456daff7a3d4ad259eab64a61c11-1]
regionserver.CompactingMemStore: Setting in-memory flush size threshold to
13421772 and immutable segments index to be of type CHUNK_MAP
2017-12-31 09:54:21,059 INFO [StoreOpener-e6ad456daff7a3d4ad259eab64a61c11-1]
regionserver.HStore: Memstore class name is
org.apache.hadoop.hbase.regionserver.CompactingMemStore
2017-12-31 09:54:21,059 INFO [StoreOpener-e6ad456daff7a3d4ad259eab64a61c11-1]
hfile.CacheConfig: Created cacheConfig for info:
blockCache=LruBlockCache{blockCount=0, currentSize=2454760,
freeSize=3347745560, maxSize=3350200320, heapSize=2454760, minSize=3182690304,
minFactor=0.95, multiSize=1591345152, multiFactor=0.5, singleSize=795672576,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2017-12-31 09:54:21,063 INFO [StoreOpener-e6ad456daff7a3d4ad259eab64a61c11-1]
compactions.CompactionConfiguration: size [134217728, 9223372036854775807,
9223372036854775807); files [3, 10); ratio 1,200000; off-peak ratio 5,000000;
throttle point 2684354560; major period 604800000, major jitter 0,500000, min
locality to compact 0,000000; tiered compaction: max_age 9223372036854775807,
incoming window min 6, compaction policy for tiered window
org.apache.hadoop.hbase.regionserver.compactions.ExploringCompactionPolicy,
single output for minor true, compaction window factory
org.apache.hadoop.hbase.regionserver.compactions.ExponentialCompactionWindowFactory
2017-12-31 09:54:21,150 INFO [RS_OPEN_REGION-node1:16020-2]
regionserver.HRegion: Setting FlushNonSloppyStoresFirstPolicy for the
region=TestTable,00000000000000000555745280,1505391191559.19d79b967c2e59cef288874533c154c8.
2017-12-31 09:54:21,234 INFO [RS_OPEN_REGION-node1:16020-0]
regionserver.HRegion: Setting FlushNonSloppyStoresFirstPolicy for the
region=TestTable,00000000000000000115343360,1505391191559.e6ad456daff7a3d4ad259eab64a61c11.
2017-12-31 09:54:21,258 INFO [RS_OPEN_REGION-node1:16020-2]
regionserver.HRegion: Onlined 19d79b967c2e59cef288874533c154c8; next
sequenceid=23352
2017-12-31 09:54:21,264 INFO
[PostOpenDeployTasks:19d79b967c2e59cef288874533c154c8]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000555745280,1505391191559.19d79b967c2e59cef288874533c154c8.
2017-12-31 09:54:21,313 INFO [RS_OPEN_REGION-node1:16020-0]
regionserver.HRegion: Onlined e6ad456daff7a3d4ad259eab64a61c11; next
sequenceid=21294
2017-12-31 09:54:21,321 INFO [RS_OPEN_REGION-node1:16020-1]
regionserver.HRegion: Setting FlushNonSloppyStoresFirstPolicy for the
region=TestTable,00000000000000000335544320,1505391191559.ba17cd27e2822b91193359a273684ac2.
2017-12-31 09:54:21,321 INFO
[PostOpenDeployTasks:e6ad456daff7a3d4ad259eab64a61c11]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000115343360,1505391191559.e6ad456daff7a3d4ad259eab64a61c11.
2017-12-31 09:54:21,380 INFO [RS_OPEN_REGION-node1:16020-1]
regionserver.HRegion: Onlined ba17cd27e2822b91193359a273684ac2; next
sequenceid=22282
2017-12-31 09:54:21,386 INFO
[PostOpenDeployTasks:ba17cd27e2822b91193359a273684ac2]
regionserver.HRegionServer: Post open deploy tasks for
TestTable,00000000000000000335544320,1505391191559.ba17cd27e2822b91193359a273684ac2.
2017-12-31 09:54:40,649 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 166b9c45d7724f72fd126adb4445d6ec without
moving
2017-12-31 09:54:40,655 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close ba17cd27e2822b91193359a273684ac2 without
moving
2017-12-31 09:54:40,680 INFO
[StoreCloserThread-TestTable,00000000000000000335544320,1505391191559.ba17cd27e2822b91193359a273684ac2.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:40,680 INFO
[StoreCloserThread-TestTable,00000000000000000262144000,1505391191559.166b9c45d7724f72fd126adb4445d6ec.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:40,702 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 98025e37220dbc821f862a91d05a96ef without
moving
2017-12-31 09:54:40,703 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 19d79b967c2e59cef288874533c154c8 without
moving
2017-12-31 09:54:40,707 INFO
[StoreCloserThread-TestTable,00000000000000000482344960,1505391191559.98025e37220dbc821f862a91d05a96ef.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:40,741 INFO [RS_CLOSE_REGION-node1:16020-0]
regionserver.HRegion: Closed
TestTable,00000000000000000262144000,1505391191559.166b9c45d7724f72fd126adb4445d6ec.
2017-12-31 09:54:40,754 INFO
[StoreCloserThread-TestTable,00000000000000000555745280,1505391191559.19d79b967c2e59cef288874533c154c8.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:40,762 INFO [RS_CLOSE_REGION-node1:16020-1]
regionserver.HRegion: Closed
TestTable,00000000000000000335544320,1505391191559.ba17cd27e2822b91193359a273684ac2.
2017-12-31 09:54:40,807 INFO [RS_CLOSE_REGION-node1:16020-2]
regionserver.HRegion: Closed
TestTable,00000000000000000482344960,1505391191559.98025e37220dbc821f862a91d05a96ef.
2017-12-31 09:54:40,839 INFO [RS_CLOSE_REGION-node1:16020-0]
regionserver.HRegion: Closed
TestTable,00000000000000000555745280,1505391191559.19d79b967c2e59cef288874533c154c8.
2017-12-31 09:54:41,102 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close f49f3cbb7f3db4cf96c7eb3b0cf83869 without
moving
2017-12-31 09:54:41,105 INFO
[StoreCloserThread-TestTable,00000000000000000408944640,1505391191559.f49f3cbb7f3db4cf96c7eb3b0cf83869.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:41,184 INFO [RS_CLOSE_REGION-node1:16020-1]
regionserver.HRegion: Closed
TestTable,00000000000000000408944640,1505391191559.f49f3cbb7f3db4cf96c7eb3b0cf83869.
2017-12-31 09:54:42,249 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close e6ad456daff7a3d4ad259eab64a61c11 without
moving
2017-12-31 09:54:42,250 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 330f09f4a0eaf26811c320fbf1b14e70 without
moving
2017-12-31 09:54:42,250 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 655b0a0608ebaecacfda2e25a7e4b0f5 without
moving
2017-12-31 09:54:42,253 INFO
[StoreCloserThread-TestTable,00000000000000000115343360,1505391191559.e6ad456daff7a3d4ad259eab64a61c11.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:42,254 INFO
[StoreCloserThread-TestTable,00000000000000000188743680,1505391191559.330f09f4a0eaf26811c320fbf1b14e70.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:42,254 INFO
[StoreCloserThread-TestTable,00000000000000000178257920,1505391191559.655b0a0608ebaecacfda2e25a7e4b0f5.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:42,341 INFO [RS_CLOSE_REGION-node1:16020-1]
regionserver.HRegion: Closed
TestTable,00000000000000000178257920,1505391191559.655b0a0608ebaecacfda2e25a7e4b0f5.
2017-12-31 09:54:42,360 INFO [RS_CLOSE_REGION-node1:16020-2]
regionserver.HRegion: Closed
TestTable,00000000000000000115343360,1505391191559.e6ad456daff7a3d4ad259eab64a61c11.
2017-12-31 09:54:42,361 INFO [RS_CLOSE_REGION-node1:16020-0]
regionserver.HRegion: Closed
TestTable,00000000000000000188743680,1505391191559.330f09f4a0eaf26811c320fbf1b14e70.
2017-12-31 09:54:42,412 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.RSRpcServices: Close 30eaa72ddc1f2706dc84c62e3222a006 without
moving
2017-12-31 09:54:42,415 INFO
[StoreCloserThread-TestTable,00000000000000000041943040,1505391191559.30eaa72ddc1f2706dc84c62e3222a006.-1]
regionserver.HStore: Closed info
2017-12-31 09:54:42,495 INFO [RS_CLOSE_REGION-node1:16020-1]
regionserver.HRegion: Closed
TestTable,00000000000000000041943040,1505391191559.30eaa72ddc1f2706dc84c62e3222a006.
2017-12-31 09:54:53,069 INFO [ReadOnlyZKClient] zookeeper.ReadOnlyZKClient:
0x1df82317 no activities for 60000 ms, close active connection. Will reconnect
next time when there are new requests.
2017-12-31 09:54:53,088 INFO [ReadOnlyZKClient] zookeeper.ZooKeeper: Session:
0x160a94d45ab0122 closed
2017-12-31 09:54:53,088 INFO [ReadOnlyZKClient-EventThread]
zookeeper.ClientCnxn: EventThread shut down for session: 0x160a94d45ab0122
...
{code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
