[jira] [Commented] (HBASE-13430) HFiles that are in use by a table cloned from a snapshot may be deleted when that snapshot is deleted

Tobi Vollebregt (JIRA) Thu, 09 Apr 2015 11:20:38 -0700

    [ 
https://issues.apache.org/jira/browse/HBASE-13430?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14487844#comment-14487844
 ]


Tobi Vollebregt commented on HBASE-13430:
-----------------------------------------

I ran it 15 times with that change and it failed only once, in a way that I've 
not seen before. The test failed because row counts between the original and 
cloned table were different, but there were no errors reading either table:

{code}
2015-04-09 10:42:03,390 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.MasterRpcServices(452): Client=tobi/null delete name: 
"snapshot_test1428601320265"
2015-04-09 10:42:03,394 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotManager(299): Deleting snapshot: snapshot_test1428601320265
2015-04-09 10:42:03,395 INFO  [IPC Server handler 9 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742366_1542 127.0.0.1:51151 127.0.0.1:62054 
2015-04-09 10:42:03,396 INFO  [IPC Server handler 9 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742368_1544 127.0.0.1:62054 127.0.0.1:51151 
2015-04-09 10:42:03,404 INFO  [B.defaultRpcServer.handler=3,queue=0,port=55405] 
master.HMaster(1301): Client=tobi/null create 'test', {NAME => 'fam', 
DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', 
VERSIONS => '1', COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 'FOREVER', 
KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 'false', 
BLOCKCACHE => 'true'}
2015-04-09 10:42:03,411 DEBUG [B.defaultRpcServer.handler=3,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test/write-master:554050000000000
2015-04-09 10:42:03,413 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(148): Create table test
2015-04-09 10:42:03,415 WARN  [main] client.ConnectionImplementation(620): 
Table test not enabled, it is not exists
2015-04-09 10:42:03,425 INFO  [IPC Server handler 7 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742375_1551{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,427 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742375_1551{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,431 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
util.FSTableDescriptors(718): Wrote descriptor into: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/.tabledesc/.tableinfo.0000000001
2015-04-09 10:42:03,433 INFO  [RegionOpenAndInitThread-test-1] 
wal.WALFactory(143): Instantiating WALProvider of type class 
org.apache.hadoop.hbase.wal.DefaultWALProvider
2015-04-09 10:42:03,436 INFO  [RegionOpenAndInitThread-test-1] wal.FSHLog(549): 
WAL configuration: blocksize=128 MB, rollsize=121.60 MB, 
prefix=hregion-53145741.default, suffix=, 
logDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-53145741,
 
archiveDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:03,448 INFO  [RegionOpenAndInitThread-test-1] 
wal.FSHLog(1494): Slow sync cost: 8 ms, current pipeline: []
2015-04-09 10:42:03,448 INFO  [RegionOpenAndInitThread-test-1] wal.FSHLog(971): 
New WAL 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-53145741/hregion-53145741.default.1428601323437
2015-04-09 10:42:03,450 INFO  [RegionOpenAndInitThread-test-1] 
regionserver.HRegion(5793): creating HRegion test HTD == 'test', {NAME => 
'fam', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE 
=> '0', VERSIONS => '1', COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 
'FOREVER', KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 
'false', BLOCKCACHE => 'true'} RootDir = 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp
 Table name == test
2015-04-09 10:42:03,463 INFO  [IPC Server handler 6 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742377_1553{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,465 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742377_1553{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,467 DEBUG [RegionOpenAndInitThread-test-1] 
regionserver.HRegion(717): Instantiated 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,467 DEBUG [RegionOpenAndInitThread-test-1] 
regionserver.HRegion(1346): Closing 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.: disabling compactions & 
flushes
2015-04-09 10:42:03,468 DEBUG [RegionOpenAndInitThread-test-1] 
regionserver.HRegion(1373): Updates disabled for region 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,468 INFO  [RegionOpenAndInitThread-test-1] 
regionserver.HRegion(1467): Closed 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,469 DEBUG [RegionOpenAndInitThread-test-1] 
wal.FSHLog(1147): Closing WAL writer in 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-53145741
2015-04-09 10:42:03,474 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742376_1552{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:03,475 INFO  [IPC Server handler 6 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742376_1552{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:03,479 DEBUG [RegionOpenAndInitThread-test-1] 
wal.FSHLog(1105): Moved 1 WAL file(s) to 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:03,480 INFO  [RegionOpenAndInitThread-test-1] 
wal.FSHLog(1108): Closed WAL: FSHLog hregion-53145741.default:(num 
1428601323437)
2015-04-09 10:42:03,488 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601323487,"tag":[],"qualifier":"state","vlen":2}]},"row":"test"}
2015-04-09 10:42:03,491 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test state to ENABLING in META
2015-04-09 10:42:03,491 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1363): 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601323491,"tag":[],"qualifier":"regioninfo","vlen":38}]},"row":"test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73."},
 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601323491,"tag":[],"qualifier":"regioninfo","vlen":38}]},"row":"test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73."}
2015-04-09 10:42:03,495 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1548): Added 2
2015-04-09 10:42:03,496 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
regionserver.HRegionFileSystem(201): No StoreFiles for: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/fam
2015-04-09 10:42:03,497 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1466): Bulk assigning 1 region(s) across 3 server(s), 
round-robin=true
2015-04-09 10:42:03,498 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(177): Timeout-on-RIT=151000
2015-04-09 10:42:03,499 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.AssignmentManager(675): Assigning 1 region(s) to 
localhost,56603,1428600966674
2015-04-09 10:42:03,501 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.RegionStates(1074): Transition {1d400dcbc03ca3bd9d4f2b979f3e4f73 
state=OFFLINE, ts=1428601323495, server=null} to 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=PENDING_OPEN, ts=1428601323501, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:03,501 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.RegionStateStore(207): Updating row 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. with 
state=PENDING_OPEN&sn=localhost,56603,1428600966674
2015-04-09 10:42:03,504 INFO  [PriorityRpcServer.handler=2,queue=0,port=56603] 
regionserver.RSRpcServices(1370): Open 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,510 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
regionserver.HRegion(5975): Opening region: {ENCODED => 
1d400dcbc03ca3bd9d4f2b979f3e4f73, NAME => 
'test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.', STARTKEY => '', ENDKEY 
=> ''}
2015-04-09 10:42:03,510 DEBUG 
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.AssignmentManager(834): Bulk assigning done for 
localhost,56603,1428600966674
2015-04-09 10:42:03,511 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl 
for table test 1d400dcbc03ca3bd9d4f2b979f3e4f73
2015-04-09 10:42:03,511 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(153): bulk assigning total 1 regions to 3 servers, 
took 12ms, with 1 regions still in transition
2015-04-09 10:42:03,512 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1473): Bulk assigning done
2015-04-09 10:42:03,512 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
regionserver.HRegion(717): Instantiated 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,513 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601323513,"tag":[],"qualifier":"state","vlen":2}]},"row":"test"}
2015-04-09 10:42:03,518 DEBUG [main] client.ConnectionImplementation(572): 
Table test not enabled
2015-04-09 10:42:03,519 INFO  [StoreOpener-1d400dcbc03ca3bd9d4f2b979f3e4f73-1] 
hfile.CacheConfig(278): blockCache=LruBlockCache{blockCount=232, 
currentSize=12155848, freeSize=324882712, maxSize=337038560, heapSize=12155848, 
minSize=320186624, minFactor=0.95, multiSize=160093312, multiFactor=0.5, 
singleSize=80046656, singleFactor=0.25}, cacheDataOnRead=true, 
cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, 
cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2015-04-09 10:42:03,519 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test state to ENABLED in META
2015-04-09 10:42:03,520 INFO  [StoreOpener-1d400dcbc03ca3bd9d4f2b979f3e4f73-1] 
compactions.CompactionConfiguration(97): size [134217728, 9223372036854775807); 
files [10, 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
2015-04-09 10:42:03,522 DEBUG [StoreOpener-1d400dcbc03ca3bd9d4f2b979f3e4f73-1] 
regionserver.HRegionFileSystem(201): No StoreFiles for: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/fam
2015-04-09 10:42:03,522 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test/write-master:554050000000000
2015-04-09 10:42:03,525 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(187): Table, test, creation successful
2015-04-09 10:42:03,525 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
regionserver.HRegion(3756): Found 0 recovered edits file(s) under 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73
2015-04-09 10:42:03,529 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
regionserver.FlushLargeStoresPolicy(56): 
hbase.hregion.percolumnfamilyflush.size.lower.bound is not specified, use 
global config(16777216) instead
2015-04-09 10:42:03,534 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
wal.WALSplitter(712): Wrote region 
seqId=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits/2.seqid
 to file, newSeqId=2, maxSeqId=0
2015-04-09 10:42:03,535 INFO  [RS_OPEN_REGION-localhost:56603-0] 
regionserver.HRegion(843): Onlined 1d400dcbc03ca3bd9d4f2b979f3e4f73; next 
sequenceid=2
2015-04-09 10:42:03,537 INFO  
[PostOpenDeployTasks:1d400dcbc03ca3bd9d4f2b979f3e4f73] 
regionserver.HRegionServer(1865): Post open deploy tasks for 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,539 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.AssignmentManager(2747): Got transition OPENED for 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=PENDING_OPEN, ts=1428601323501, 
server=localhost,56603,1428600966674} from localhost,56603,1428600966674
2015-04-09 10:42:03,540 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStates(1074): Transition {1d400dcbc03ca3bd9d4f2b979f3e4f73 
state=PENDING_OPEN, ts=1428601323501, server=localhost,56603,1428600966674} to 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=OPEN, ts=1428601323540, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:03,540 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStateStore(207): Updating row 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. with 
state=OPEN&openSeqNum=2&server=localhost,56603,1428600966674
2015-04-09 10:42:03,543 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStates(420): Onlined 1d400dcbc03ca3bd9d4f2b979f3e4f73 on 
localhost,56603,1428600966674 {ENCODED => 1d400dcbc03ca3bd9d4f2b979f3e4f73, 
NAME => 'test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.', STARTKEY => 
'', ENDKEY => ''}
2015-04-09 10:42:03,545 DEBUG 
[PostOpenDeployTasks:1d400dcbc03ca3bd9d4f2b979f3e4f73] 
regionserver.HRegionServer(1892): Finished post open deploy task for 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:03,546 DEBUG [RS_OPEN_REGION-localhost:56603-0] 
handler.OpenRegionHandler(122): Opened 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. on 
localhost,56603,1428600966674
2015-04-09 10:42:03,724 DEBUG [main] client.ConnectionImplementation(615): 
Table test should be available
2015-04-09 10:42:03,729 INFO  [main] hbase.Waiter(189): Waiting up to [60,000] 
milli-secs(wait.for.ratio=[1])
2015-04-09 10:42:03,741 INFO  [main] hbase.Waiter(189): Waiting up to [60,000] 
milli-secs(wait.for.ratio=[1])
2015-04-09 10:42:03,743 INFO  [B.defaultRpcServer.handler=2,queue=0,port=55405] 
master.HMaster(1301): Client=tobi/null create 'test1428601323742', {NAME => 
'fam', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE 
=> '0', VERSIONS => '1', COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 
'FOREVER', KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 
'false', BLOCKCACHE => 'true'}
2015-04-09 10:42:03,749 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test1428601323742/write-master:554050000000000
2015-04-09 10:42:03,750 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(148): Create table test1428601323742
2015-04-09 10:42:03,752 WARN  [Thread-4502] 
client.ConnectionImplementation(620): Table test1428601323742 not enabled, it 
is not exists
2015-04-09 10:42:03,761 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742378_1554{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,763 INFO  [IPC Server handler 8 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742378_1554{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,766 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
util.FSTableDescriptors(718): Wrote descriptor into: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test1428601323742/.tabledesc/.tableinfo.0000000001
2015-04-09 10:42:03,768 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
wal.WALFactory(143): Instantiating WALProvider of type class 
org.apache.hadoop.hbase.wal.DefaultWALProvider
2015-04-09 10:42:03,771 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(549): WAL configuration: blocksize=128 MB, rollsize=121.60 MB, 
prefix=hregion-03217128.default, suffix=, 
logDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-03217128,
 
archiveDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:03,781 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(1494): Slow sync cost: 6 ms, current pipeline: []
2015-04-09 10:42:03,781 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(971): New WAL 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-03217128/hregion-03217128.default.1428601323772
2015-04-09 10:42:03,783 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
regionserver.HRegion(5793): creating HRegion test1428601323742 HTD == 
'test1428601323742', {NAME => 'fam', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER 
=> 'NONE', REPLICATION_SCOPE => '0', VERSIONS => '1', COMPRESSION => 'NONE', 
MIN_VERSIONS => '0', TTL => 'FOREVER', KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE 
=> '65536', IN_MEMORY => 'false', BLOCKCACHE => 'true'} RootDir = 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp
 Table name == test1428601323742
2015-04-09 10:42:03,798 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742380_1556{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:03,800 INFO  [IPC Server handler 8 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to blk_1073742380_1556 size 52
2015-04-09 10:42:03,800 DEBUG [RegionOpenAndInitThread-test1428601323742-1] 
regionserver.HRegion(717): Instantiated 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,801 DEBUG [RegionOpenAndInitThread-test1428601323742-1] 
regionserver.HRegion(1346): Closing 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.: disabling 
compactions & flushes
2015-04-09 10:42:03,802 DEBUG [RegionOpenAndInitThread-test1428601323742-1] 
regionserver.HRegion(1373): Updates disabled for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,803 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
regionserver.HRegion(1467): Closed 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,803 DEBUG [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(1147): Closing WAL writer in 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-03217128
2015-04-09 10:42:03,808 INFO  [IPC Server handler 7 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742379_1555{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:03,809 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742379_1555{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:03,812 DEBUG [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(1105): Moved 1 WAL file(s) to 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:03,813 INFO  [RegionOpenAndInitThread-test1428601323742-1] 
wal.FSHLog(1108): Closed WAL: FSHLog hregion-03217128.default:(num 
1428601323772)
2015-04-09 10:42:03,821 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601323821,"tag":[],"qualifier":"state","vlen":2}]},"row":"test1428601323742"}
2015-04-09 10:42:03,826 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test1428601323742 state to 
ENABLING in META
2015-04-09 10:42:03,827 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1363): 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601323826,"tag":[],"qualifier":"regioninfo","vlen":51}]},"row":"test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd."},
 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601323827,"tag":[],"qualifier":"regioninfo","vlen":51}]},"row":"test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd."}
2015-04-09 10:42:03,832 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1548): Added 2
2015-04-09 10:42:03,834 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
regionserver.HRegionFileSystem(201): No StoreFiles for: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam
2015-04-09 10:42:03,835 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1466): Bulk assigning 1 region(s) across 3 server(s), 
round-robin=true
2015-04-09 10:42:03,837 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(177): Timeout-on-RIT=151000
2015-04-09 10:42:03,837 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.AssignmentManager(675): Assigning 1 region(s) to 
localhost,56603,1428600966674
2015-04-09 10:42:03,840 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.RegionStates(1074): Transition {1dd03fbb6d470404223ed69a05ed33bd 
state=OFFLINE, ts=1428601323833, server=null} to 
{1dd03fbb6d470404223ed69a05ed33bd state=PENDING_OPEN, ts=1428601323840, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:03,841 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.RegionStateStore(207): Updating row 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. with 
state=PENDING_OPEN&sn=localhost,56603,1428600966674
2015-04-09 10:42:03,844 INFO  [PriorityRpcServer.handler=1,queue=1,port=56603] 
regionserver.RSRpcServices(1370): Open 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,851 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
regionserver.HRegion(5975): Opening region: {ENCODED => 
1dd03fbb6d470404223ed69a05ed33bd, NAME => 
'test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.', STARTKEY 
=> '', ENDKEY => ''}
2015-04-09 10:42:03,851 DEBUG 
[localhost,55405,1428600961198-GeneralBulkAssigner-2] 
master.AssignmentManager(834): Bulk assigning done for 
localhost,56603,1428600966674
2015-04-09 10:42:03,852 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl 
for table test1428601323742 1dd03fbb6d470404223ed69a05ed33bd
2015-04-09 10:42:03,852 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(153): bulk assigning total 1 regions to 3 servers, 
took 13ms, with 1 regions still in transition
2015-04-09 10:42:03,853 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
regionserver.HRegion(717): Instantiated 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,853 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1473): Bulk assigning done
2015-04-09 10:42:03,855 DEBUG [Thread-4502] 
client.ConnectionImplementation(572): Table test1428601323742 not enabled
2015-04-09 10:42:03,855 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601323855,"tag":[],"qualifier":"state","vlen":2}]},"row":"test1428601323742"}
2015-04-09 10:42:03,857 INFO  [StoreOpener-1dd03fbb6d470404223ed69a05ed33bd-1] 
hfile.CacheConfig(278): blockCache=LruBlockCache{blockCount=232, 
currentSize=12155848, freeSize=324882712, maxSize=337038560, heapSize=12155848, 
minSize=320186624, minFactor=0.95, multiSize=160093312, multiFactor=0.5, 
singleSize=80046656, singleFactor=0.25}, cacheDataOnRead=true, 
cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, 
cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2015-04-09 10:42:03,859 INFO  [StoreOpener-1dd03fbb6d470404223ed69a05ed33bd-1] 
compactions.CompactionConfiguration(97): size [134217728, 9223372036854775807); 
files [10, 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
2015-04-09 10:42:03,859 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test1428601323742 state to ENABLED 
in META
2015-04-09 10:42:03,860 DEBUG [StoreOpener-1dd03fbb6d470404223ed69a05ed33bd-1] 
regionserver.HRegionFileSystem(201): No StoreFiles for: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam
2015-04-09 10:42:03,862 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
regionserver.HRegion(3756): Found 0 recovered edits file(s) under 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd
2015-04-09 10:42:03,862 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test1428601323742/write-master:554050000000000
2015-04-09 10:42:03,863 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(187): Table, test1428601323742, creation successful
2015-04-09 10:42:03,864 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
regionserver.FlushLargeStoresPolicy(56): 
hbase.hregion.percolumnfamilyflush.size.lower.bound is not specified, use 
global config(16777216) instead
2015-04-09 10:42:03,868 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
wal.WALSplitter(712): Wrote region 
seqId=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/recovered.edits/2.seqid
 to file, newSeqId=2, maxSeqId=0
2015-04-09 10:42:03,869 INFO  [RS_OPEN_REGION-localhost:56603-1] 
regionserver.HRegion(843): Onlined 1dd03fbb6d470404223ed69a05ed33bd; next 
sequenceid=2
2015-04-09 10:42:03,871 INFO  
[PostOpenDeployTasks:1dd03fbb6d470404223ed69a05ed33bd] 
regionserver.HRegionServer(1865): Post open deploy tasks for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,872 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.AssignmentManager(2747): Got transition OPENED for 
{1dd03fbb6d470404223ed69a05ed33bd state=PENDING_OPEN, ts=1428601323840, 
server=localhost,56603,1428600966674} from localhost,56603,1428600966674
2015-04-09 10:42:03,873 INFO  [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.RegionStates(1074): Transition {1dd03fbb6d470404223ed69a05ed33bd 
state=PENDING_OPEN, ts=1428601323840, server=localhost,56603,1428600966674} to 
{1dd03fbb6d470404223ed69a05ed33bd state=OPEN, ts=1428601323873, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:03,874 INFO  [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.RegionStateStore(207): Updating row 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. with 
state=OPEN&openSeqNum=2&server=localhost,56603,1428600966674
2015-04-09 10:42:03,876 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.RegionStates(420): Onlined 1dd03fbb6d470404223ed69a05ed33bd on 
localhost,56603,1428600966674 {ENCODED => 1dd03fbb6d470404223ed69a05ed33bd, 
NAME => 'test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.', 
STARTKEY => '', ENDKEY => ''}
2015-04-09 10:42:03,878 DEBUG 
[PostOpenDeployTasks:1dd03fbb6d470404223ed69a05ed33bd] 
regionserver.HRegionServer(1892): Finished post open deploy task for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:03,879 DEBUG [RS_OPEN_REGION-localhost:56603-1] 
handler.OpenRegionHandler(122): Opened 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. on 
localhost,56603,1428600966674
2015-04-09 10:42:04,061 DEBUG [Thread-4502] 
client.ConnectionImplementation(615): Table test1428601323742 should be 
available
2015-04-09 10:42:04,065 INFO  [Thread-4502] hbase.Waiter(189): Waiting up to 
[60,000] milli-secs(wait.for.ratio=[1])
2015-04-09 10:42:04,078 INFO  [Thread-4502] hbase.Waiter(189): Waiting up to 
[60,000] milli-secs(wait.for.ratio=[1])
2015-04-09 10:42:04,133 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:04,133 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:04,138 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=56603] 
regionserver.HRegion(3695): Flush requested on 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:04,138 DEBUG [MemStoreFlusher.0] 
regionserver.FlushLargeStoresPolicy(100): Since none of the CFs were above the 
size, flushing all.
2015-04-09 10:42:04,142 INFO  [MemStoreFlusher.0] regionserver.HRegion(2087): 
Started memstore flush for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., current 
region memstore size 731.56 KB, and 1/1 column families' memstores are being 
flushed.
2015-04-09 10:42:04,163 INFO  [IPC Server handler 2 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742381_1557{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,165 INFO  [IPC Server handler 8 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742381_1557{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,167 INFO  [MemStoreFlusher.0] 
regionserver.DefaultStoreFlusher(87): Flushed, sequenceid=6, memsize=731.6 K, 
hasBloomFilter=false, into tmp file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/2bc664716d4048c1a07169a2ec9ace89
2015-04-09 10:42:04,183 DEBUG [MemStoreFlusher.0] 
regionserver.HRegionFileSystem(381): Committing store file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/2bc664716d4048c1a07169a2ec9ace89
 as 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89
2015-04-09 10:42:04,195 INFO  [MemStoreFlusher.0] regionserver.HStore(973): 
Added 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89,
 entries=4682, sequenceid=6, filesize=151.1 K
2015-04-09 10:42:04,197 INFO  [MemStoreFlusher.0] regionserver.HRegion(2366): 
Finished memstore flush of ~731.56 KB/749120, currentsize=0 B/0 for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. in 55ms, 
sequenceid=6, compaction requested=false
2015-04-09 10:42:04,285 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:04,285 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:04,467 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=56603] 
regionserver.HRegion(3695): Flush requested on 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:04,467 DEBUG [MemStoreFlusher.1] 
regionserver.FlushLargeStoresPolicy(100): Since none of the CFs were above the 
size, flushing all.
2015-04-09 10:42:04,468 INFO  [MemStoreFlusher.1] regionserver.HRegion(2087): 
Started memstore flush for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., current 
region memstore size 731.56 KB, and 1/1 column families' memstores are being 
flushed.
2015-04-09 10:42:04,489 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742382_1558{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,490 INFO  [IPC Server handler 6 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742382_1558{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,492 INFO  [MemStoreFlusher.1] 
regionserver.DefaultStoreFlusher(87): Flushed, sequenceid=11, memsize=731.6 K, 
hasBloomFilter=false, into tmp file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/fd8c337769d94420941b41150504a638
2015-04-09 10:42:04,507 DEBUG [MemStoreFlusher.1] 
regionserver.HRegionFileSystem(381): Committing store file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/fd8c337769d94420941b41150504a638
 as 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638
2015-04-09 10:42:04,517 INFO  [MemStoreFlusher.1] regionserver.HStore(973): 
Added 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638,
 entries=4682, sequenceid=11, filesize=151.1 K
2015-04-09 10:42:04,519 INFO  [MemStoreFlusher.1] regionserver.HRegion(2366): 
Finished memstore flush of ~731.56 KB/749120, currentsize=0 B/0 for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. in 50ms, 
sequenceid=11, compaction requested=false
2015-04-09 10:42:04,542 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:04,542 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:04,741 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=56603] 
regionserver.HRegion(3695): Flush requested on 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:04,741 DEBUG [MemStoreFlusher.0] 
regionserver.FlushLargeStoresPolicy(100): Since none of the CFs were above the 
size, flushing all.
2015-04-09 10:42:04,756 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:04,756 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:04,756 INFO  [MemStoreFlusher.0] regionserver.HRegion(2087): 
Started memstore flush for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., current 
region memstore size 731.56 KB, and 1/1 column families' memstores are being 
flushed.
2015-04-09 10:42:04,772 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742383_1559{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,773 INFO  [IPC Server handler 5 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742383_1559{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:04,775 INFO  [MemStoreFlusher.0] 
regionserver.DefaultStoreFlusher(87): Flushed, sequenceid=16, memsize=731.6 K, 
hasBloomFilter=false, into tmp file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/fdf6cd4e1c0b4b5285f876099479078e
2015-04-09 10:42:04,788 DEBUG [MemStoreFlusher.0] 
regionserver.HRegionFileSystem(381): Committing store file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/fdf6cd4e1c0b4b5285f876099479078e
 as 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e
2015-04-09 10:42:04,800 INFO  [MemStoreFlusher.0] regionserver.HStore(973): 
Added 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e,
 entries=4682, sequenceid=16, filesize=151.1 K
2015-04-09 10:42:04,802 INFO  [MemStoreFlusher.0] regionserver.HRegion(2366): 
Finished memstore flush of ~731.56 KB/749120, currentsize=0 B/0 for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. in 46ms, 
sequenceid=16, compaction requested=false
2015-04-09 10:42:04,983 DEBUG [B.defaultRpcServer.handler=1,queue=0,port=56603] 
regionserver.HRegion(3695): Flush requested on 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:04,983 DEBUG [MemStoreFlusher.1] 
regionserver.FlushLargeStoresPolicy(100): Since none of the CFs were above the 
size, flushing all.
2015-04-09 10:42:04,984 INFO  [MemStoreFlusher.1] regionserver.HRegion(2087): 
Started memstore flush for 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., current 
region memstore size 551.56 KB, and 1/1 column families' memstores are being 
flushed.
2015-04-09 10:42:04,986 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.MasterRpcServices(1181): Client=tobi/null snapshot request for:{ 
ss=snapshot_test1428601323742 table=test1428601323742 type=FLUSH }
2015-04-09 10:42:04,987 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotDescriptionUtils(235): Creation time not specified, setting 
to:1428601324987 (current time:1428601324987).
2015-04-09 10:42:04,987 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotManager(543): No existing snapshot, attempting snapshot...
2015-04-09 10:42:04,989 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotManager(587): Table enabled, starting distributed snapshot.
2015-04-09 10:42:04,992 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test1428601323742/write-master:554050000000001
2015-04-09 10:42:04,993 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotManager(589): Started snapshot: { 
ss=snapshot_test1428601323742 table=test1428601323742 type=FLUSH }
2015-04-09 10:42:04,993 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.TakeSnapshotHandler(160): Running FLUSH table snapshot 
snapshot_test1428601323742 C_M_SNAPSHOT_TABLE on table test1428601323742
2015-04-09 10:42:04,994 DEBUG [Thread-4502] client.HBaseAdmin(3036): Waiting a 
max of 60000 ms for snapshot '{ ss=snapshot_test1428601323742 
table=test1428601323742 type=FLUSH }'' to complete. (max 1714 ms per retry)
2015-04-09 10:42:04,994 DEBUG [Thread-4502] client.HBaseAdmin(3045): (#1) 
Sleeping: 100ms while waiting for snapshot completion.
2015-04-09 10:42:05,004 INFO  [IPC Server handler 6 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742385_1561{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,005 INFO  [IPC Server handler 2 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742385_1561{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,016 INFO  
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(196): Starting procedure 'snapshot_test1428601323742'
2015-04-09 10:42:05,016 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
errorhandling.TimeoutExceptionInjector(108): Scheduling process timer to run 
in: 60000 ms
2015-04-09 10:42:05,019 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(204): Procedure 'snapshot_test1428601323742' starting 
'acquire'
2015-04-09 10:42:05,020 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(246): Starting procedure 'snapshot_test1428601323742', 
kicking off acquire phase on members.
2015-04-09 10:42:05,022 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
zookeeper.ZKUtil(488): master:55405-0x14c9f40b6350000, quorum=localhost:56477, 
baseZNode=/hbase Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/abort/snapshot_test1428601323742
2015-04-09 10:42:05,023 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.ZKProcedureCoordinatorRpcs(93): Creating acquire 
znode:/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,025 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,025 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.ZKProcedureCoordinatorRpcs(101): Watching for acquire 
node:/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,025 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:56603-0x14c9f40b6350001, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,025 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:51009-0x14c9f40b6350002, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,027 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,027 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,027 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
zookeeper.ZKUtil(488): master:55405-0x14c9f40b6350000, quorum=localhost:56477, 
baseZNode=/hbase Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,028 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(208): Waiting for all members to 'acquire'
2015-04-09 10:42:05,025 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,029 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,028 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(184): Found procedure znode: 
/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,027 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,030 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,030 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(184): Found procedure znode: 
/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,031 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(184): Found procedure znode: 
/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,030 DEBUG [main-EventThread] zookeeper.ZKUtil(488): 
regionserver:56603-0x14c9f40b6350001, quorum=localhost:56477, baseZNode=/hbase 
Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/abort/snapshot_test1428601323742
2015-04-09 10:42:05,031 DEBUG [main-EventThread] zookeeper.ZKUtil(488): 
regionserver:51009-0x14c9f40b6350002, quorum=localhost:56477, baseZNode=/hbase 
Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/abort/snapshot_test1428601323742
2015-04-09 10:42:05,031 DEBUG [main-EventThread] zookeeper.ZKUtil(488): 
master:55405-0x14c9f40b6350000, quorum=localhost:56477, baseZNode=/hbase Set 
watcher on znode that does not yet exist, 
/hbase/online-snapshot/abort/snapshot_test1428601323742
2015-04-09 10:42:05,032 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(210): start proc data length is 62
2015-04-09 10:42:05,033 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(212): Found data for 
znode:/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,032 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(210): start proc data length is 62
2015-04-09 10:42:05,034 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(212): Found data for 
znode:/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,034 DEBUG [main-EventThread] 
snapshot.RegionServerSnapshotManager(175): Launching subprocedure for snapshot 
snapshot_test1428601323742 from table test1428601323742
2015-04-09 10:42:05,033 DEBUG [main-EventThread] 
snapshot.RegionServerSnapshotManager(175): Launching subprocedure for snapshot 
snapshot_test1428601323742 from table test1428601323742
2015-04-09 10:42:05,033 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(210): start proc data length is 62
2015-04-09 10:42:05,036 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(212): Found data for 
znode:/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,037 DEBUG [main-EventThread] 
snapshot.RegionServerSnapshotManager(175): Launching subprocedure for snapshot 
snapshot_test1428601323742 from table test1428601323742
2015-04-09 10:42:05,035 DEBUG [main-EventThread] 
procedure.ProcedureMember(154): Submitting new 
Subprocedure:snapshot_test1428601323742
2015-04-09 10:42:05,038 DEBUG [main-EventThread] 
procedure.ProcedureMember(154): Submitting new 
Subprocedure:snapshot_test1428601323742
2015-04-09 10:42:05,036 DEBUG [main-EventThread] 
procedure.ProcedureMember(154): Submitting new 
Subprocedure:snapshot_test1428601323742
2015-04-09 10:42:05,039 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(152): Starting subprocedure 
'snapshot_test1428601323742' with timeout 60000ms
2015-04-09 10:42:05,040 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] errorhandling.TimeoutExceptionInjector(108): 
Scheduling process timer to run in: 60000 ms
2015-04-09 10:42:05,038 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(152): Starting subprocedure 
'snapshot_test1428601323742' with timeout 60000ms
2015-04-09 10:42:05,042 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(160): Subprocedure 
'snapshot_test1428601323742' starting 'acquire' stage
2015-04-09 10:42:05,042 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(162): Subprocedure 
'snapshot_test1428601323742' locally acquired
2015-04-09 10:42:05,043 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.ZKProcedureMemberRpcs(241): Member: 
'localhost,55405,1428600961198' joining acquired barrier for procedure 
(snapshot_test1428601323742) in zk
2015-04-09 10:42:05,039 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(152): Starting subprocedure 
'snapshot_test1428601323742' with timeout 60000ms
2015-04-09 10:42:05,042 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] errorhandling.TimeoutExceptionInjector(108): 
Scheduling process timer to run in: 60000 ms
2015-04-09 10:42:05,043 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] errorhandling.TimeoutExceptionInjector(108): 
Scheduling process timer to run in: 60000 ms
2015-04-09 10:42:05,045 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(160): Subprocedure 
'snapshot_test1428601323742' starting 'acquire' stage
2015-04-09 10:42:05,047 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(162): Subprocedure 
'snapshot_test1428601323742' locally acquired
2015-04-09 10:42:05,048 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.ZKProcedureMemberRpcs(241): Member: 
'localhost,56603,1428600966674' joining acquired barrier for procedure 
(snapshot_test1428601323742) in zk
2015-04-09 10:42:05,047 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.ZKProcedureMemberRpcs(249): Watch for 
global barrier reached:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,047 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(160): Subprocedure 
'snapshot_test1428601323742' starting 'acquire' stage
2015-04-09 10:42:05,050 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(162): Subprocedure 
'snapshot_test1428601323742' locally acquired
2015-04-09 10:42:05,050 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.ZKProcedureMemberRpcs(249): Watch for 
global barrier reached:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,050 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] zookeeper.ZKUtil(488): 
master:55405-0x14c9f40b6350000, quorum=localhost:56477, baseZNode=/hbase Set 
watcher on znode that does not yet exist, 
/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,051 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] zookeeper.ZKUtil(488): 
regionserver:56603-0x14c9f40b6350001, quorum=localhost:56477, baseZNode=/hbase 
Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,052 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(167): Subprocedure 
'snapshot_test1428601323742' coordinator notified of 'acquire', waiting on 
'reached' or 'abort' from coordinator
2015-04-09 10:42:05,050 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.ZKProcedureMemberRpcs(241): Member: 
'localhost,51009,1428600971935' joining acquired barrier for procedure 
(snapshot_test1428601323742) in zk
2015-04-09 10:42:05,050 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeCreated, state=SyncConnected, 
path=/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,052 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(167): Subprocedure 
'snapshot_test1428601323742' coordinator notified of 'acquire', waiting on 
'reached' or 'abort' from coordinator
2015-04-09 10:42:05,054 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.ZKProcedureMemberRpcs(249): Watch for 
global barrier reached:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,054 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(79): Received created 
event:/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,055 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] zookeeper.ZKUtil(488): 
regionserver:51009-0x14c9f40b6350002, quorum=localhost:56477, baseZNode=/hbase 
Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,056 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(167): Subprocedure 
'snapshot_test1428601323742' coordinator notified of 'acquire', waiting on 
'reached' or 'abort' from coordinator
2015-04-09 10:42:05,055 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(99): Ignoring created notification for 
node:/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,057 DEBUG [main-EventThread] 
procedure.ZKProcedureCoordinatorRpcs$1(186): Node created: 
/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,057 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(244): Current zk system:
2015-04-09 10:42:05,057 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(246): |-/hbase/online-snapshot
2015-04-09 10:42:05,058 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-acquired
2015-04-09 10:42:05,059 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |----snapshot_test1428601323742
2015-04-09 10:42:05,059 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,56603,1428600966674
2015-04-09 10:42:05,060 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,55405,1428600961198
2015-04-09 10:42:05,060 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,51009,1428600971935
2015-04-09 10:42:05,061 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-abort
2015-04-09 10:42:05,061 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-reached
2015-04-09 10:42:05,062 DEBUG [main-EventThread] procedure.Procedure(297): 
member: 'localhost,56603,1428600966674' joining acquired barrier for procedure 
'snapshot_test1428601323742' on coordinator
2015-04-09 10:42:05,062 DEBUG [main-EventThread] procedure.Procedure(306): 
Waiting on: java.util.concurrent.CountDownLatch@3dd1dd9c[Count = 0] remaining 
members to acquire global barrier
2015-04-09 10:42:05,062 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(212): Procedure 'snapshot_test1428601323742' starting 
'in-barrier' execution.
2015-04-09 10:42:05,063 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.ZKProcedureCoordinatorRpcs(115): Creating reached barrier zk 
node:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,064 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:51009-0x14c9f40b6350002, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeCreated, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,065 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
zookeeper.ZKUtil(488): master:55405-0x14c9f40b6350000, quorum=localhost:56477, 
baseZNode=/hbase Set watcher on znode that does not yet exist, 
/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,064 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:56603-0x14c9f40b6350001, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeCreated, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,064 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeCreated, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,066 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(79): Received created 
event:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,067 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(130): Recieved reached global 
barrier:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,065 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(79): Received created 
event:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,067 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(181): Subprocedure 
'snapshot_test1428601323742' received 'reached' from coordinator.
2015-04-09 10:42:05,067 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(79): Received created 
event:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,068 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(130): Recieved reached global 
barrier:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,067 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(130): Recieved reached global 
barrier:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,069 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(181): Subprocedure 
'snapshot_test1428601323742' received 'reached' from coordinator.
2015-04-09 10:42:05,069 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(183): Subprocedure 
'snapshot_test1428601323742' locally completed
2015-04-09 10:42:05,068 DEBUG [main-EventThread] 
procedure.ZKProcedureCoordinatorRpcs$1(186): Node created: 
/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,070 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(244): Current zk system:
2015-04-09 10:42:05,070 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(246): |-/hbase/online-snapshot
2015-04-09 10:42:05,068 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.FlushSnapshotSubprocedure$RegionSnapshotTask(85): Starting region 
operation on test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:05,068 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] snapshot.FlushSnapshotSubprocedure(138): Flush 
Snapshot Tasks submitted for 1 regions
2015-04-09 10:42:05,071 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] 
snapshot.RegionServerSnapshotManager$SnapshotSubprocedurePool(311): Waiting for 
local region snapshots to finish.
2015-04-09 10:42:05,071 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.FlushSnapshotSubprocedure$RegionSnapshotTask(98): Flush Snapshotting 
region test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. 
started...
2015-04-09 10:42:05,071 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-acquired
2015-04-09 10:42:05,070 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.ZKProcedureMemberRpcs(265): Marking 
procedure  'snapshot_test1428601323742' completed for member 
'localhost,55405,1428600961198' in zk
2015-04-09 10:42:05,069 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(181): Subprocedure 
'snapshot_test1428601323742' received 'reached' from coordinator.
2015-04-09 10:42:05,072 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |----snapshot_test1428601323742
2015-04-09 10:42:05,072 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
regionserver.HRegion(1870): NOT flushing memstore for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., 
flushing=true, writesEnabled=true
2015-04-09 10:42:05,074 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,56603,1428600966674
2015-04-09 10:42:05,074 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(188): Subprocedure 
'snapshot_test1428601323742' has notified controller of completion
2015-04-09 10:42:05,074 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,55405,1428600961198
2015-04-09 10:42:05,073 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(183): Subprocedure 
'snapshot_test1428601323742' locally completed
2015-04-09 10:42:05,075 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,51009,1428600971935
2015-04-09 10:42:05,074 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] errorhandling.TimeoutExceptionInjector(88): 
Marking timer as complete - no error notifications will be received for this 
timer.
2015-04-09 10:42:05,074 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(163): Storing 
'test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.' 
region-info for snapshot.
2015-04-09 10:42:05,076 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-abort
2015-04-09 10:42:05,076 DEBUG [member: 'localhost,55405,1428600961198' 
subprocedure-pool2-thread-1] procedure.Subprocedure(213): Subprocedure 
'snapshot_test1428601323742' completed.
2015-04-09 10:42:05,075 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.ZKProcedureMemberRpcs(265): Marking 
procedure  'snapshot_test1428601323742' completed for member 
'localhost,51009,1428600971935' in zk
2015-04-09 10:42:05,078 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-reached
2015-04-09 10:42:05,077 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(168): Creating references for hfiles
2015-04-09 10:42:05,079 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |----snapshot_test1428601323742
2015-04-09 10:42:05,079 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(177): Adding snapshot references for 
[hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89,
 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638,
 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e]
 hfiles
2015-04-09 10:42:05,081 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(186): Adding reference for file (1/3): 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89
2015-04-09 10:42:05,080 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,55405,1428600961198
2015-04-09 10:42:05,080 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(188): Subprocedure 
'snapshot_test1428601323742' has notified controller of completion
2015-04-09 10:42:05,083 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] errorhandling.TimeoutExceptionInjector(88): 
Marking timer as complete - no error notifications will be received for this 
timer.
2015-04-09 10:42:05,082 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,51009,1428600971935
2015-04-09 10:42:05,082 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(186): Adding reference for file (2/3): 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638
2015-04-09 10:42:05,085 DEBUG [main-EventThread] 
procedure.ZKProcedureCoordinatorRpcs$1(228): Ignoring created notification for 
node:/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,083 DEBUG [member: 'localhost,51009,1428600971935' 
subprocedure-pool4-thread-1] procedure.Subprocedure(213): Subprocedure 
'snapshot_test1428601323742' completed.
2015-04-09 10:42:05,086 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.SnapshotManifest(186): Adding reference for file (3/3): 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e
2015-04-09 10:42:05,095 DEBUG [Thread-4502] client.HBaseAdmin(3051): Getting 
current status of snapshot from master...
2015-04-09 10:42:05,096 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742386_1562{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,097 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.MasterRpcServices(951): Checking to see if snapshot from request:{ 
ss=snapshot_test1428601323742 table=test1428601323742 type=FLUSH } is done
2015-04-09 10:42:05,097 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742386_1562{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,097 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
snapshot.SnapshotManager(372): Snapshoting '{ ss=snapshot_test1428601323742 
table=test1428601323742 type=FLUSH }' is still in progress!
2015-04-09 10:42:05,099 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.FlushSnapshotSubprocedure$RegionSnapshotTask(105): ... Flush 
Snapshotting region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. completed.
2015-04-09 10:42:05,099 DEBUG [Thread-4502] client.HBaseAdmin(3045): (#2) 
Sleeping: 200ms while waiting for snapshot completion.
2015-04-09 10:42:05,099 DEBUG 
[rs(localhost,56603,1428600966674)-snapshot-pool54-thread-1] 
snapshot.FlushSnapshotSubprocedure$RegionSnapshotTask(108): Closing region 
operation on test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:05,100 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] 
snapshot.RegionServerSnapshotManager$SnapshotSubprocedurePool(322): Completed 
1/1 local region snapshots.
2015-04-09 10:42:05,100 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] 
snapshot.RegionServerSnapshotManager$SnapshotSubprocedurePool(324): Completed 1 
local region snapshots.
2015-04-09 10:42:05,101 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] 
snapshot.RegionServerSnapshotManager$SnapshotSubprocedurePool(352): cancelling 
0 tasks for snapshot localhost,56603,1428600966674
2015-04-09 10:42:05,101 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(183): Subprocedure 
'snapshot_test1428601323742' locally completed
2015-04-09 10:42:05,101 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.ZKProcedureMemberRpcs(265): Marking 
procedure  'snapshot_test1428601323742' completed for member 
'localhost,56603,1428600966674' in zk
2015-04-09 10:42:05,103 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(188): Subprocedure 
'snapshot_test1428601323742' has notified controller of completion
2015-04-09 10:42:05,103 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeCreated, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,104 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] errorhandling.TimeoutExceptionInjector(88): 
Marking timer as complete - no error notifications will be received for this 
timer.
2015-04-09 10:42:05,104 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(79): Received created 
event:/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,105 DEBUG [member: 'localhost,56603,1428600966674' 
subprocedure-pool3-thread-1] procedure.Subprocedure(213): Subprocedure 
'snapshot_test1428601323742' completed.
2015-04-09 10:42:05,106 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(99): Ignoring created notification for 
node:/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,107 DEBUG [main-EventThread] 
procedure.ZKProcedureCoordinatorRpcs$1(186): Node created: 
/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,107 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(244): Current zk system:
2015-04-09 10:42:05,107 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(246): |-/hbase/online-snapshot
2015-04-09 10:42:05,108 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-acquired
2015-04-09 10:42:05,108 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |----snapshot_test1428601323742
2015-04-09 10:42:05,109 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,56603,1428600966674
2015-04-09 10:42:05,109 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,55405,1428600961198
2015-04-09 10:42:05,110 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,51009,1428600971935
2015-04-09 10:42:05,110 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-abort
2015-04-09 10:42:05,111 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-reached
2015-04-09 10:42:05,112 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |----snapshot_test1428601323742
2015-04-09 10:42:05,112 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,56603,1428600966674
2015-04-09 10:42:05,113 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,55405,1428600961198
2015-04-09 10:42:05,113 DEBUG [main-EventThread] 
procedure.ZKProcedureUtil(263): |-------localhost,51009,1428600971935
2015-04-09 10:42:05,114 DEBUG [main-EventThread] 
procedure.ZKProcedureCoordinatorRpcs$1(211): Finished data from procedure 
'snapshot_test1428601323742' member 'localhost,56603,1428600966674': 
2015-04-09 10:42:05,115 DEBUG [main-EventThread] procedure.Procedure(328): 
Member: 'localhost,56603,1428600966674' released barrier for 
procedure'snapshot_test1428601323742', counting down latch.  Waiting for 0 more
2015-04-09 10:42:05,115 INFO  
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(220): Procedure 'snapshot_test1428601323742' execution 
completed
2015-04-09 10:42:05,115 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(229): Running finish phase.
2015-04-09 10:42:05,116 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.Procedure(280): Finished coordinator procedure - removing self from 
list of running procedures
2015-04-09 10:42:05,116 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.ZKProcedureCoordinatorRpcs(157): Attempting to clean out zk node for 
op:snapshot_test1428601323742
2015-04-09 10:42:05,116 INFO  
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
procedure.ZKProcedureUtil(284): Clearing all znodes for procedure 
snapshot_test1428601323742including nodes /hbase/online-snapshot/acquired 
/hbase/online-snapshot/reached /hbase/online-snapshot/abort
2015-04-09 10:42:05,118 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,119 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,55405,1428600961198
2015-04-09 10:42:05,120 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/acquired/snapshot_test1428601323742/localhost,51009,1428600971935
2015-04-09 10:42:05,121 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/acquired/snapshot_test1428601323742
2015-04-09 10:42:05,121 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:51009-0x14c9f40b6350002, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,121 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): regionserver:56603-0x14c9f40b6350001, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,122 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,123 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,122 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeChildrenChanged, state=SyncConnected, 
path=/hbase/online-snapshot/acquired
2015-04-09 10:42:05,123 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,124 INFO  [main-EventThread] 
procedure.ZKProcedureMemberRpcs$1(106): Received procedure start children 
changed event: /hbase/online-snapshot/acquired
2015-04-09 10:42:05,125 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,124 DEBUG [main-EventThread] 
procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under 
znode:'/hbase/online-snapshot/acquired'
2015-04-09 10:42:05,126 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,56603,1428600966674
2015-04-09 10:42:05,126 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,55405,1428600961198
2015-04-09 10:42:05,126 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742/localhost,51009,1428600971935
2015-04-09 10:42:05,127 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.EnabledTableSnapshotHandler(96): Done waiting - online snapshot for 
snapshot_test1428601323742
2015-04-09 10:42:05,127 DEBUG 
[(localhost,55405,1428600961198)-proc-coordinator-pool1-thread-1] 
errorhandling.TimeoutExceptionInjector(88): Marking timer as complete - no 
error notifications will be received for this timer.
2015-04-09 10:42:05,127 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.SnapshotManifest(361): Convert to Single Snapshot Manifest
2015-04-09 10:42:05,127 DEBUG [main-EventThread] 
zookeeper.ZooKeeperWatcher(388): master:55405-0x14c9f40b6350000, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, 
type=NodeDeleted, state=SyncConnected, 
path=/hbase/online-snapshot/reached/snapshot_test1428601323742
2015-04-09 10:42:05,129 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.SnapshotManifestV1(119): No regions under 
directory:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.hbase-snapshot/.tmp/snapshot_test1428601323742
2015-04-09 10:42:05,144 INFO  [IPC Server handler 6 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742387_1563{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,145 INFO  [IPC Server handler 2 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742387_1563{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:05,147 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742386_1562 127.0.0.1:51151 127.0.0.1:62054 
2015-04-09 10:42:05,167 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.TakeSnapshotHandler(254): Sentinel is done, just moving the snapshot 
from 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.hbase-snapshot/.tmp/snapshot_test1428601323742
 to 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.hbase-snapshot/snapshot_test1428601323742
2015-04-09 10:42:05,169 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.TakeSnapshotHandler(206): Snapshot snapshot_test1428601323742 of table 
test1428601323742 completed
2015-04-09 10:42:05,169 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.TakeSnapshotHandler(219): Launching cleanup of working 
dir:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.hbase-snapshot/.tmp/snapshot_test1428601323742
2015-04-09 10:42:05,172 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test1428601323742/write-master:554050000000001
2015-04-09 10:42:05,300 DEBUG [Thread-4502] client.HBaseAdmin(3051): Getting 
current status of snapshot from master...
2015-04-09 10:42:05,302 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.MasterRpcServices(951): Checking to see if snapshot from request:{ 
ss=snapshot_test1428601323742 table=test1428601323742 type=FLUSH } is done
2015-04-09 10:42:05,302 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
snapshot.SnapshotManager(369): Snapshot '{ ss=snapshot_test1428601323742 
table=test1428601323742 type=FLUSH }' has completed, notifying client.
2015-04-09 10:42:05,311 INFO  [Thread-4502] 
zookeeper.RecoverableZooKeeper(121): Process 
identifier=hbase-admin-on-hconnection-0x271fedd connecting to ZooKeeper 
ensemble=localhost:56477
2015-04-09 10:42:06,453 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:06,453 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:06,913 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:10,390 DEBUG [Thread-4502-EventThread] 
zookeeper.ZooKeeperWatcher(388): hbase-admin-on-hconnection-0x271fedd0x0, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, type=None, 
state=SyncConnected, path=null
2015-04-09 10:42:10,392 DEBUG [Thread-4502-EventThread] 
zookeeper.ZooKeeperWatcher(472): 
hbase-admin-on-hconnection-0x271fedd-0x14c9f40b6350044 connected
2015-04-09 10:42:10,402 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test-clone-test1428601323742/write-master:554050000000000
2015-04-09 10:42:10,403 INFO  [B.defaultRpcServer.handler=2,queue=0,port=55405] 
snapshot.SnapshotManager(749): Clone snapshot=snapshot_test1428601323742 as 
table=test-clone-test1428601323742
2015-04-09 10:42:10,403 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(148): Create table test-clone-test1428601323742
2015-04-09 10:42:10,404 DEBUG [Thread-4502] client.HBaseAdmin(3506): 1) 
Sleeping: 100 ms while we wait for snapshot restore to complete.
2015-04-09 10:42:10,409 INFO  [IPC Server handler 8 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742388_1564{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,410 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742388_1564{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,412 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
util.FSTableDescriptors(718): Wrote descriptor into: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test-clone-test1428601323742/.tabledesc/.tableinfo.0000000001
2015-04-09 10:42:10,415 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.RestoreSnapshotHelper(164): starting restore
2015-04-09 10:42:10,415 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.RestoreSnapshotHelper(664): get table regions: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test-clone-test1428601323742
2015-04-09 10:42:10,416 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.RestoreSnapshotHelper(214): region to add: 
1dd03fbb6d470404223ed69a05ed33bd
2015-04-09 10:42:10,416 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.RestoreSnapshotHelper(502): clone 
region=1dd03fbb6d470404223ed69a05ed33bd as 0022e3f6af87a83c597249cec0f69acc
2015-04-09 10:42:10,416 INFO  [RestoreSnapshot-pool230-t1] wal.WALFactory(143): 
Instantiating WALProvider of type class 
org.apache.hadoop.hbase.wal.DefaultWALProvider
2015-04-09 10:42:10,418 INFO  [RestoreSnapshot-pool230-t1] wal.FSHLog(549): WAL 
configuration: blocksize=128 MB, rollsize=121.60 MB, 
prefix=hregion-92311738.default, suffix=, 
logDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-92311738,
 
archiveDir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:10,426 INFO  [RestoreSnapshot-pool230-t1] wal.FSHLog(1494): 
Slow sync cost: 5 ms, current pipeline: []
2015-04-09 10:42:10,427 INFO  [RestoreSnapshot-pool230-t1] wal.FSHLog(971): New 
WAL 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-92311738/hregion-92311738.default.1428601330419
2015-04-09 10:42:10,427 INFO  [RestoreSnapshot-pool230-t1] 
regionserver.HRegion(5793): creating HRegion test-clone-test1428601323742 HTD 
== 'test-clone-test1428601323742', {NAME => 'fam', DATA_BLOCK_ENCODING => 
'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', VERSIONS => '1', 
COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 'FOREVER', 
KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 'false', 
BLOCKCACHE => 'true'} RootDir = 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp
 Table name == test-clone-test1428601323742
2015-04-09 10:42:10,436 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742390_1566{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,437 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742390_1566{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,439 DEBUG [RestoreSnapshot-pool230-t1] 
regionserver.HRegion(717): Instantiated 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,439 INFO  [RestoreSnapshot-pool230-t1] 
snapshot.RestoreSnapshotHelper(539): Adding HFileLink 
2bc664716d4048c1a07169a2ec9ace89 to table=test-clone-test1428601323742
2015-04-09 10:42:10,444 INFO  [RestoreSnapshot-pool230-t1] 
snapshot.RestoreSnapshotHelper(539): Adding HFileLink 
fd8c337769d94420941b41150504a638 to table=test-clone-test1428601323742
2015-04-09 10:42:10,450 INFO  [RestoreSnapshot-pool230-t1] 
snapshot.RestoreSnapshotHelper(539): Adding HFileLink 
fdf6cd4e1c0b4b5285f876099479078e to table=test-clone-test1428601323742
2015-04-09 10:42:10,455 DEBUG [RestoreSnapshot-pool230-t1] 
regionserver.HRegion(1346): Closing 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.: 
disabling compactions & flushes
2015-04-09 10:42:10,455 DEBUG [RestoreSnapshot-pool230-t1] 
regionserver.HRegion(1373): Updates disabled for region 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,456 INFO  [RestoreSnapshot-pool230-t1] 
regionserver.HRegion(1467): Closed 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,456 DEBUG [RestoreSnapshot-pool230-t1] wal.FSHLog(1147): 
Closing WAL writer in 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/WALs/hregion-92311738
2015-04-09 10:42:10,459 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742389_1565{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:10,460 INFO  [IPC Server handler 9 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742389_1565{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW]]}
 size 83
2015-04-09 10:42:10,462 DEBUG [RestoreSnapshot-pool230-t1] wal.FSHLog(1105): 
Moved 1 WAL file(s) to 
/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/oldWALs
2015-04-09 10:42:10,462 INFO  [RestoreSnapshot-pool230-t1] wal.FSHLog(1108): 
Closed WAL: FSHLog hregion-92311738.default:(num 1428601330419)
2015-04-09 10:42:10,463 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
snapshot.CloneSnapshotHandler(123): Clone snapshot=snapshot_test1428601323742 
on table=test-clone-test1428601323742 completed!
2015-04-09 10:42:10,468 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601330468,"tag":[],"qualifier":"state","vlen":2}]},"row":"test-clone-test1428601323742"}
2015-04-09 10:42:10,470 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test-clone-test1428601323742 state 
to ENABLING in META
2015-04-09 10:42:10,471 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1363): 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601330470,"tag":[],"qualifier":"regioninfo","vlen":62}]},"row":"test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc."},
 
Put{"totalColumns":1,"families":{"info":[{"timestamp":1428601330470,"tag":[],"qualifier":"regioninfo","vlen":62}]},"row":"test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc."}
2015-04-09 10:42:10,473 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1548): Added 2
2015-04-09 10:42:10,477 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1466): Bulk assigning 1 region(s) across 3 server(s), 
round-robin=true
2015-04-09 10:42:10,478 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-0] 
master.AssignmentManager(675): Assigning 1 region(s) to 
localhost,51009,1428600971935
2015-04-09 10:42:10,478 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(177): Timeout-on-RIT=151000
2015-04-09 10:42:10,479 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-0] 
master.RegionStates(1074): Transition {0022e3f6af87a83c597249cec0f69acc 
state=OFFLINE, ts=1428601330473, server=null} to 
{0022e3f6af87a83c597249cec0f69acc state=PENDING_OPEN, ts=1428601330479, 
server=localhost,51009,1428600971935}
2015-04-09 10:42:10,479 INFO  
[localhost,55405,1428600961198-GeneralBulkAssigner-0] 
master.RegionStateStore(207): Updating row 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc. 
with state=PENDING_OPEN&sn=localhost,51009,1428600971935
2015-04-09 10:42:10,481 INFO  [PriorityRpcServer.handler=3,queue=1,port=51009] 
regionserver.RSRpcServices(1370): Open 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,483 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
regionserver.HRegion(5975): Opening region: {ENCODED => 
0022e3f6af87a83c597249cec0f69acc, NAME => 
'test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.',
 STARTKEY => '', ENDKEY => ''}
2015-04-09 10:42:10,484 DEBUG 
[localhost,55405,1428600961198-GeneralBulkAssigner-0] 
master.AssignmentManager(834): Bulk assigning done for 
localhost,51009,1428600971935
2015-04-09 10:42:10,484 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl 
for table test-clone-test1428601323742 0022e3f6af87a83c597249cec0f69acc
2015-04-09 10:42:10,484 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.GeneralBulkAssigner(153): bulk assigning total 1 regions to 3 servers, 
took 6ms, with 1 regions still in transition
2015-04-09 10:42:10,485 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
regionserver.HRegion(717): Instantiated 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,485 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
master.AssignmentManager(1473): Bulk assigning done
2015-04-09 10:42:10,486 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601330486,"tag":[],"qualifier":"state","vlen":2}]},"row":"test-clone-test1428601323742"}
2015-04-09 10:42:10,487 INFO  [StoreOpener-0022e3f6af87a83c597249cec0f69acc-1] 
hfile.CacheConfig(278): blockCache=LruBlockCache{blockCount=232, 
currentSize=12155848, freeSize=324882712, maxSize=337038560, heapSize=12155848, 
minSize=320186624, minFactor=0.95, multiSize=160093312, multiFactor=0.5, 
singleSize=80046656, singleFactor=0.25}, cacheDataOnRead=true, 
cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, 
cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2015-04-09 10:42:10,488 INFO  [StoreOpener-0022e3f6af87a83c597249cec0f69acc-1] 
compactions.CompactionConfiguration(97): size [134217728, 9223372036854775807); 
files [10, 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
2015-04-09 10:42:10,488 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test-clone-test1428601323742 state 
to ENABLED in META
2015-04-09 10:42:10,489 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test-clone-test1428601323742/write-master:554050000000000
2015-04-09 10:42:10,490 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.CreateTableHandler(187): Table, test-clone-test1428601323742, creation 
successful
2015-04-09 10:42:10,495 DEBUG [StoreOpener-0022e3f6af87a83c597249cec0f69acc-1] 
regionserver.HStore(549): loaded 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test-clone-test1428601323742/0022e3f6af87a83c597249cec0f69acc/fam/test1428601323742=1dd03fbb6d470404223ed69a05ed33bd-2bc664716d4048c1a07169a2ec9ace89,
 isReference=false, isBulkLoadResult=false, seqid=6, majorCompaction=false
2015-04-09 10:42:10,499 DEBUG [StoreOpener-0022e3f6af87a83c597249cec0f69acc-1] 
regionserver.HStore(549): loaded 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test-clone-test1428601323742/0022e3f6af87a83c597249cec0f69acc/fam/test1428601323742=1dd03fbb6d470404223ed69a05ed33bd-fd8c337769d94420941b41150504a638,
 isReference=false, isBulkLoadResult=false, seqid=11, majorCompaction=false
2015-04-09 10:42:10,503 DEBUG [StoreOpener-0022e3f6af87a83c597249cec0f69acc-1] 
regionserver.HStore(549): loaded 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test-clone-test1428601323742/0022e3f6af87a83c597249cec0f69acc/fam/test1428601323742=1dd03fbb6d470404223ed69a05ed33bd-fdf6cd4e1c0b4b5285f876099479078e,
 isReference=false, isBulkLoadResult=false, seqid=16, majorCompaction=false
2015-04-09 10:42:10,504 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
regionserver.HRegion(3756): Found 0 recovered edits file(s) under 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test-clone-test1428601323742/0022e3f6af87a83c597249cec0f69acc
2015-04-09 10:42:10,504 DEBUG [Thread-4502] client.HBaseAdmin(3512): Getting 
current status of snapshot restore from master...
2015-04-09 10:42:10,506 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
snapshot.SnapshotManager(824): Verify snapshot=snapshot_test1428601323742 
against=snapshot_test1428601323742 table=test-clone-test1428601323742
2015-04-09 10:42:10,506 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
regionserver.FlushLargeStoresPolicy(56): 
hbase.hregion.percolumnfamilyflush.size.lower.bound is not specified, use 
global config(16777216) instead
2015-04-09 10:42:10,507 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
snapshot.SnapshotManager(833): Restore snapshot={ ss=snapshot_test1428601323742 
table=test-clone-test1428601323742 type=FLUSH } has completed. Notifying the 
client.
2015-04-09 10:42:10,510 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
wal.WALSplitter(712): Wrote region 
seqId=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test-clone-test1428601323742/0022e3f6af87a83c597249cec0f69acc/recovered.edits/17.seqid
 to file, newSeqId=17, maxSeqId=0
2015-04-09 10:42:10,510 INFO  [RS_OPEN_REGION-localhost:51009-2] 
regionserver.HRegion(843): Onlined 0022e3f6af87a83c597249cec0f69acc; next 
sequenceid=17
2015-04-09 10:42:10,511 INFO  
[PostOpenDeployTasks:0022e3f6af87a83c597249cec0f69acc] 
regionserver.HRegionServer(1865): Post open deploy tasks for 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,512 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=55405] 
master.AssignmentManager(2747): Got transition OPENED for 
{0022e3f6af87a83c597249cec0f69acc state=PENDING_OPEN, ts=1428601330479, 
server=localhost,51009,1428600971935} from localhost,51009,1428600971935
2015-04-09 10:42:10,512 DEBUG [Thread-4502] 
client.ConnectionImplementation(584): Table test-clone-test1428601323742 has 
not deployed region 0022e3f6af87a83c597249cec0f69acc
2015-04-09 10:42:10,513 DEBUG [Thread-4502] 
client.ConnectionImplementation(604): Table test-clone-test1428601323742 has 1 
regions
2015-04-09 10:42:10,512 INFO  [B.defaultRpcServer.handler=2,queue=0,port=55405] 
master.RegionStates(1074): Transition {0022e3f6af87a83c597249cec0f69acc 
state=PENDING_OPEN, ts=1428601330479, server=localhost,51009,1428600971935} to 
{0022e3f6af87a83c597249cec0f69acc state=OPEN, ts=1428601330512, 
server=localhost,51009,1428600971935}
2015-04-09 10:42:10,513 DEBUG [Thread-4502] client.HBaseAdmin(866): Sleeping= 
100ms, waiting for all regions to be enabled in test-clone-test1428601323742
2015-04-09 10:42:10,513 INFO  [B.defaultRpcServer.handler=2,queue=0,port=55405] 
master.RegionStateStore(207): Updating row 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc. 
with state=OPEN&openSeqNum=17&server=localhost,51009,1428600971935
2015-04-09 10:42:10,515 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=55405] 
master.RegionStates(420): Onlined 0022e3f6af87a83c597249cec0f69acc on 
localhost,51009,1428600971935 {ENCODED => 0022e3f6af87a83c597249cec0f69acc, 
NAME => 
'test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.',
 STARTKEY => '', ENDKEY => ''}
2015-04-09 10:42:10,516 DEBUG 
[PostOpenDeployTasks:0022e3f6af87a83c597249cec0f69acc] 
regionserver.HRegionServer(1892): Finished post open deploy task for 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc.
2015-04-09 10:42:10,517 DEBUG [RS_OPEN_REGION-localhost:51009-2] 
handler.OpenRegionHandler(122): Opened 
test-clone-test1428601323742,,1428601323743.0022e3f6af87a83c597249cec0f69acc. 
on localhost,51009,1428600971935
2015-04-09 10:42:10,624 DEBUG [Thread-4502] 
client.ConnectionImplementation(615): Table test-clone-test1428601323742 should 
be available
2015-04-09 10:42:10,626 INFO  [Thread-4502] 
zookeeper.RecoverableZooKeeper(121): Process 
identifier=hbase-admin-on-hconnection-0x271fedd connecting to ZooKeeper 
ensemble=localhost:56477
2015-04-09 10:42:10,630 DEBUG [Thread-4502-EventThread] 
zookeeper.ZooKeeperWatcher(388): hbase-admin-on-hconnection-0x271fedd0x0, 
quorum=localhost:56477, baseZNode=/hbase Received ZooKeeper Event, type=None, 
state=SyncConnected, path=null
2015-04-09 10:42:10,638 DEBUG [Thread-4502-EventThread] 
zookeeper.ZooKeeperWatcher(472): 
hbase-admin-on-hconnection-0x271fedd-0x14c9f40b6350045 connected
2015-04-09 10:42:10,639 INFO  [PriorityRpcServer.handler=3,queue=1,port=56603] 
regionserver.RSRpcServices(1051): Compacting 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:10,639 DEBUG [PriorityRpcServer.handler=3,queue=1,port=56603] 
compactions.RatioBasedCompactionPolicy(92): Selecting compaction from 3 store 
files, 0 compacting, 3 eligible, 12 blocking
2015-04-09 10:42:10,640 DEBUG [PriorityRpcServer.handler=3,queue=1,port=56603] 
regionserver.HStore(1578): 1dd03fbb6d470404223ed69a05ed33bd - fam: Initiating 
major compaction (all files)
2015-04-09 10:42:10,641 DEBUG [PriorityRpcServer.handler=3,queue=1,port=56603] 
regionserver.CompactSplitThread(355): Small Compaction requested: 
org.apache.hadoop.hbase.regionserver.DefaultStoreEngine$DefaultCompactionContext@4e456e83;
 Because: User-triggered major compaction; compaction_queue=(0:0), 
split_queue=0, merge_queue=0
2015-04-09 10:42:10,641 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.HRegion(1773): Starting compaction on fam in region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.
2015-04-09 10:42:10,651 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.HStore(1206): Starting compaction of 3 file(s) in fam of 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. into 
tmpdir=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp,
 totalSize=453.2 K
2015-04-09 10:42:10,654 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
compactions.Compactor(169): Compacting 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89,
 keycount=4682, bloomtype=NONE, size=151.1 K, encoding=NONE, seqNum=6, 
earliestPutTs=1428601324101
2015-04-09 10:42:10,654 INFO  [B.defaultRpcServer.handler=0,queue=0,port=55405] 
master.MasterRpcServices(452): Client=tobi/null delete name: 
"snapshot_test1428601323742"

2015-04-09 10:42:10,656 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
compactions.Compactor(169): Compacting 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638,
 keycount=4682, bloomtype=NONE, size=151.1 K, encoding=NONE, seqNum=11, 
earliestPutTs=1428601324454
2015-04-09 10:42:10,657 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:10,657 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
compactions.Compactor(169): Compacting 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e,
 keycount=4682, bloomtype=NONE, size=151.1 K, encoding=NONE, seqNum=16, 
earliestPutTs=1428601324729
2015-04-09 10:42:10,659 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=55405] 
snapshot.SnapshotManager(299): Deleting snapshot: snapshot_test1428601323742
2015-04-09 10:42:10,660 INFO  [IPC Server handler 2 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742385_1561 127.0.0.1:51151 127.0.0.1:62054 
2015-04-09 10:42:10,661 INFO  [IPC Server handler 2 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742387_1563 127.0.0.1:51151 127.0.0.1:62054 
2015-04-09 10:42:10,667 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] hfile.CacheConfig(278): 
blockCache=LruBlockCache{blockCount=232, currentSize=12155848, 
freeSize=324882712, maxSize=337038560, heapSize=12155848, minSize=320186624, 
minFactor=0.95, multiSize=160093312, multiFactor=0.5, singleSize=80046656, 
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, 
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, 
cacheDataCompressed=false, prefetchOnOpen=false
2015-04-09 10:42:10,697 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] 
compactions.PressureAwareCompactionThroughputController(239): 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd.#fam average 
throughput is 15.54 MB/sec, slept 0 time(s) and total slept time is 0 ms. 0 
active compactions remaining, total limit is 10.00 MB/sec
2015-04-09 10:42:10,702 INFO  [IPC Server handler 3 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742391_1567{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,703 INFO  [IPC Server handler 9 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742391_1567{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-3a8e39f3-6bc2-444e-a514-44be3e57456d:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-efc94249-4e28-488d-9899-1bfcc3a8c5a6:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:10,722 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.HRegionFileSystem(381): Committing store file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/64260352e743477f99de49262cca9c5c
 as 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/64260352e743477f99de49262cca9c5c
2015-04-09 10:42:10,731 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.HStore(1713): Removing store files after compaction...
2015-04-09 10:42:10,732 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
backup.HFileArchiver(224): Archiving compacted store files.
2015-04-09 10:42:10,738 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
backup.HFileArchiver(438): Finished archiving from class 
org.apache.hadoop.hbase.backup.HFileArchiver$FileableStoreFile, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89,
 to 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/archive/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/2bc664716d4048c1a07169a2ec9ace89
2015-04-09 10:42:10,740 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
backup.HFileArchiver(438): Finished archiving from class 
org.apache.hadoop.hbase.backup.HFileArchiver$FileableStoreFile, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638,
 to 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/archive/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fd8c337769d94420941b41150504a638
2015-04-09 10:42:10,743 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
backup.HFileArchiver(438): Finished archiving from class 
org.apache.hadoop.hbase.backup.HFileArchiver$FileableStoreFile, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e,
 to 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/archive/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/fdf6cd4e1c0b4b5285f876099479078e
2015-04-09 10:42:10,744 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.HStore(1334): Completed major compaction of 3 (all) file(s) in fam 
of test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. into 
64260352e743477f99de49262cca9c5c(size=416.5 K), total size for store is 416.5 
K. This selection was in queue for 0sec, and took 0sec to execute.
2015-04-09 10:42:10,745 INFO  
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.CompactSplitThread$CompactionRunner(523): Completed compaction: 
Request = 
regionName=test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd., 
storeName=fam, fileCount=3, fileSize=453.2 K, priority=1, 
time=1428601330640642000; duration=0sec
2015-04-09 10:42:10,746 DEBUG 
[RS:0;localhost:56603-shortCompactions-1428600995506] 
regionserver.CompactSplitThread$CompactionRunner(546): CompactSplitThread 
Status: compaction_queue=(0:0), split_queue=0, merge_queue=0
2015-04-09 10:42:11,047 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:12,431 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:12,438 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:12,547 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:13,764 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:14,932 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:14,959 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:17,229 DEBUG [localhost,55405,1428600961198_ChoreService_1] 
compactions.PressureAwareCompactionThroughputController(148): 
compactionPressure is 0.0, tune compaction throughput to 10.00 MB/sec
2015-04-09 10:42:17,229 DEBUG [localhost,56603,1428600966674_ChoreService_1] 
compactions.PressureAwareCompactionThroughputController(148): 
compactionPressure is 0.0, tune compaction throughput to 10.00 MB/sec
2015-04-09 10:42:17,230 DEBUG [localhost,51009,1428600971935_ChoreService_1] 
compactions.PressureAwareCompactionThroughputController(148): 
compactionPressure is 0.0, tune compaction throughput to 10.00 MB/sec
2015-04-09 10:42:18,839 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:19,467 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:20,258 INFO  [IPC Server handler 4 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:62054 is added to 
blk_1073742384_1560{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:20,259 INFO  [IPC Server handler 0 on 62612] 
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 
127.0.0.1:51151 is added to 
blk_1073742384_1560{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-123b77a2-3384-49ae-a717-7921a3abcc17:NORMAL|RBW],
 
ReplicaUnderConstruction[[DISK]DS-6c4e4034-a262-4dc5-ad9b-ea95a50195d7:NORMAL|RBW]]}
 size 0
2015-04-09 10:42:20,260 INFO  [MemStoreFlusher.1] 
regionserver.DefaultStoreFlusher(87): Flushed, sequenceid=21, memsize=551.6 K, 
hasBloomFilter=false, into tmp file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/62eb491a641a4841a2613e16b6e2ecaf
2015-04-09 10:42:20,274 DEBUG [MemStoreFlusher.1] 
regionserver.HRegionFileSystem(381): Committing store file 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/.tmp/62eb491a641a4841a2613e16b6e2ecaf
 as 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/62eb491a641a4841a2613e16b6e2ecaf
2015-04-09 10:42:20,280 INFO  [MemStoreFlusher.1] regionserver.HStore(973): 
Added 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test1428601323742/1dd03fbb6d470404223ed69a05ed33bd/fam/62eb491a641a4841a2613e16b6e2ecaf,
 entries=3530, sequenceid=21, filesize=115.0 K
2015-04-09 10:42:20,281 INFO  [MemStoreFlusher.1] regionserver.HRegion(2366): 
Finished memstore flush of ~551.56 KB/564800, currentsize=0 B/0 for region 
test1428601323742,,1428601323743.1dd03fbb6d470404223ed69a05ed33bd. in 15297ms, 
sequenceid=21, compaction requested=false
2015-04-09 10:42:20,645 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:20,741 INFO  [main] client.HBaseAdmin$10(981): Started disable 
of test
2015-04-09 10:42:20,742 INFO  [B.defaultRpcServer.handler=3,queue=0,port=55405] 
master.HMaster(1643): Client=tobi/null disable test
2015-04-09 10:42:20,744 DEBUG [B.defaultRpcServer.handler=3,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test/write-master:554050000000001
2015-04-09 10:42:20,746 DEBUG [B.defaultRpcServer.handler=3,queue=0,port=55405] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601340746,"tag":[],"qualifier":"state","vlen":2}]},"row":"test"}
2015-04-09 10:42:20,749 INFO  [B.defaultRpcServer.handler=3,queue=0,port=55405] 
hbase.MetaTableAccessor(1672): Updated table test state to DISABLING in META
2015-04-09 10:42:20,749 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DisableTableHandler(123): Attempting to disable table test
2015-04-09 10:42:20,749 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601340749,"tag":[],"qualifier":"state","vlen":2}]},"row":"test"}
2015-04-09 10:42:20,751 DEBUG [main] client.HBaseAdmin(1021): Sleeping= 100ms, 
waiting for all regions to be disabled in test
2015-04-09 10:42:20,752 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test state to DISABLING in META
2015-04-09 10:42:20,752 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DisableTableHandler(166): Offlining 1 regions.
2015-04-09 10:42:20,753 DEBUG 
[localhost,55405,1428600961198-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
 master.AssignmentManager(1283): Starting unassign of 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. (offlining), current 
state: {1d400dcbc03ca3bd9d4f2b979f3e4f73 state=OPEN, ts=1428601323540, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:20,754 INFO  
[localhost,55405,1428600961198-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
 master.RegionStates(1074): Transition {1d400dcbc03ca3bd9d4f2b979f3e4f73 
state=OPEN, ts=1428601323540, server=localhost,56603,1428600966674} to 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=PENDING_CLOSE, ts=1428601340754, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:20,754 INFO  
[localhost,55405,1428600961198-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
 master.RegionStateStore(207): Updating row 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. with state=PENDING_CLOSE
2015-04-09 10:42:20,756 INFO  [PriorityRpcServer.handler=5,queue=1,port=56603] 
regionserver.RSRpcServices(1026): Close 1d400dcbc03ca3bd9d4f2b979f3e4f73, 
moving to null
2015-04-09 10:42:20,756 DEBUG [RS_CLOSE_REGION-localhost:56603-2] 
handler.CloseRegionHandler(90): Processing close of 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:20,757 DEBUG 
[localhost,55405,1428600961198-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
 master.AssignmentManager(867): Sent CLOSE to localhost,56603,1428600966674 for 
region test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:20,758 DEBUG [RS_CLOSE_REGION-localhost:56603-2] 
regionserver.HRegion(1346): Closing 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.: disabling compactions & 
flushes
2015-04-09 10:42:20,759 DEBUG [RS_CLOSE_REGION-localhost:56603-2] 
regionserver.HRegion(1373): Updates disabled for region 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:20,760 INFO  
[StoreCloserThread-test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.-1] 
regionserver.HStore(879): Closed fam
2015-04-09 10:42:20,764 DEBUG [RS_CLOSE_REGION-localhost:56603-2] 
wal.WALSplitter(712): Wrote region 
seqId=hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits/4.seqid
 to file, newSeqId=4, maxSeqId=2
2015-04-09 10:42:20,765 INFO  [RS_CLOSE_REGION-localhost:56603-2] 
regionserver.HRegion(1467): Closed 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:20,766 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.AssignmentManager(2747): Got transition CLOSED for 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=PENDING_CLOSE, ts=1428601340754, 
server=localhost,56603,1428600966674} from localhost,56603,1428600966674
2015-04-09 10:42:20,768 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStates(1074): Transition {1d400dcbc03ca3bd9d4f2b979f3e4f73 
state=PENDING_CLOSE, ts=1428601340754, server=localhost,56603,1428600966674} to 
{1d400dcbc03ca3bd9d4f2b979f3e4f73 state=OFFLINE, ts=1428601340768, 
server=localhost,56603,1428600966674}
2015-04-09 10:42:20,769 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStateStore(207): Updating row 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. with state=OFFLINE
2015-04-09 10:42:20,771 INFO  [B.defaultRpcServer.handler=4,queue=0,port=55405] 
master.RegionStates(560): Offlined 1d400dcbc03ca3bd9d4f2b979f3e4f73 from 
localhost,56603,1428600966674
2015-04-09 10:42:20,772 DEBUG [RS_CLOSE_REGION-localhost:56603-2] 
handler.CloseRegionHandler(122): Closed 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.
2015-04-09 10:42:20,804 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1344): 
Put{"totalColumns":1,"families":{"table":[{"timestamp":1428601340803,"tag":[],"qualifier":"state","vlen":2}]},"row":"test"}
2015-04-09 10:42:20,806 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1672): Updated table test state to DISABLED in META
2015-04-09 10:42:20,806 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DisableTableHandler(183): Disabled table, test, is done=true
2015-04-09 10:42:20,808 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test/write-master:554050000000001
2015-04-09 10:42:20,854 INFO  [main] client.HBaseAdmin(1036): Disabled test
2015-04-09 10:42:20,855 INFO  [B.defaultRpcServer.handler=3,queue=0,port=55405] 
master.HMaster(1548): Client=tobi/null delete test
2015-04-09 10:42:20,858 DEBUG [B.defaultRpcServer.handler=3,queue=0,port=55405] 
lock.ZKInterProcessLockBase(226): Acquired a lock for 
/hbase/table-lock/test/write-master:554050000000002
2015-04-09 10:42:20,861 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.TableEventHandler(127): Handling table operation C_M_DELETE_TABLE on 
table test
2015-04-09 10:42:20,870 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(176): Deleting regions from META
2015-04-09 10:42:20,871 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1395): 
Delete{"ts":9223372036854775807,"totalColumns":1,"families":{"info":[{"timestamp":1428601340871,"tag":[],"qualifier":"","vlen":0}]},"row":"test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73."}
2015-04-09 10:42:20,876 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1809): Deleted [{ENCODED => 
1d400dcbc03ca3bd9d4f2b979f3e4f73, NAME => 
'test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73.', STARTKEY => '', ENDKEY 
=> ''}]
2015-04-09 10:42:20,878 INFO  [localhost,55405,1428600961198_ChoreService_2] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:20,879 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(191): Archiving region 
test,,1428601323404.1d400dcbc03ca3bd9d4f2b979f3e4f73. from FS
2015-04-09 10:42:20,879 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
backup.HFileArchiver(93): ARCHIVING 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73
2015-04-09 10:42:20,882 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
backup.HFileArchiver(134): Archiving [class 
org.apache.hadoop.hbase.backup.HFileArchiver$FileablePath, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/fam,
 class org.apache.hadoop.hbase.backup.HFileArchiver$FileablePath, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits]
2015-04-09 10:42:20,890 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
backup.HFileArchiver(438): Finished archiving from class 
org.apache.hadoop.hbase.backup.HFileArchiver$FileablePath, 
file:hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits/4.seqid,
 to 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/archive/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits/4.seqid
2015-04-09 10:42:20,892 INFO  [IPC Server handler 1 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742377_1553 127.0.0.1:62054 127.0.0.1:51151 
2015-04-09 10:42:20,893 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
backup.HFileArchiver(453): Deleted all region files in: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/.tmp/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73
2015-04-09 10:42:20,894 INFO  [IPC Server handler 3 on 62612] 
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: 
blk_1073742375_1551 127.0.0.1:51151 127.0.0.1:62054 
2015-04-09 10:42:20,895 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(201): Table 'test' archived!
2015-04-09 10:42:20,895 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(123): Removing 'test' descriptor.
2015-04-09 10:42:20,895 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(129): Removing 'test' from region states.
2015-04-09 10:42:20,908 INFO  [localhost,55405,1428600961198_ChoreService_1] 
hbase.ScheduledChore(175): Chore: LogsCleaner missed its start time
2015-04-09 10:42:20,908 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
handler.DeleteTableHandler(137): Marking 'test' as deleted.
2015-04-09 10:42:20,909 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1395): 
Delete{"ts":9223372036854775807,"totalColumns":1,"families":{"table":[{"timestamp":1428601340909,"tag":[],"qualifier":"state","vlen":0}]},"row":"test"}
2015-04-09 10:42:20,910 INFO  [localhost,55405,1428600961198_ChoreService_3] 
hbase.ScheduledChore(175): Chore: HFileCleaner missed its start time
2015-04-09 10:42:20,912 INFO  [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
hbase.MetaTableAccessor(1698): Deleted table test state from META
2015-04-09 10:42:20,913 DEBUG [localhost,55405,1428600961198_ChoreService_2] 
cleaner.CleanerChore(255): Removing: 
hdfs://localhost:62612/user/tobi/test-data/53918d72-650f-448a-b7b7-29ccc9e77b97/archive/data/default/test/1d400dcbc03ca3bd9d4f2b979f3e4f73/recovered.edits/4.seqid
 from archive
2015-04-09 10:42:20,923 DEBUG [MASTER_TABLE_OPERATIONS-localhost:55405-0] 
lock.ZKInterProcessLockBase(328): Released 
/hbase/table-lock/test/write-master:554050000000002
2015-04-09 10:42:20,965 INFO  [main] client.HBaseAdmin(741): Deleted test

java.lang.AssertionError: 
Expected :17576
Actual   :14046
 <Click to see difference>
  at org.junit.Assert.fail(Assert.java:88)
  at org.junit.Assert.failNotEquals(Assert.java:743)
  at org.junit.Assert.assertEquals(Assert.java:118)
  at org.junit.Assert.assertEquals(Assert.java:555)
  at org.junit.Assert.assertEquals(Assert.java:542)
  at 
org.apache.hadoop.hbase.client.TestSnapshotCloneIndependence.runTestSnapshotDeleteIndependent(TestSnapshotCloneIndependence.java:434)
  at 
org.apache.hadoop.hbase.client.TestSnapshotCloneIndependence.testOnlineSnapshotDeleteIndependent(TestSnapshotCloneIndependence.java:191)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
  at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
  at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
  at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
  at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
  at 
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
{code}

In good news though, before swapping the check order in HFileLinkCleaner it 
fails > 50% of the time for me, but after it failed only 1 out of 15 times, and 
not with DFS errors because of missing HFiles.

I'm going to prepare a patch combining my earlier two batches and 
[~mbertozzi]'s change. 

> HFiles that are in use by a table cloned from a snapshot may be deleted when 
> that snapshot is deleted
> -----------------------------------------------------------------------------------------------------
>
>                 Key: HBASE-13430
>                 URL: https://issues.apache.org/jira/browse/HBASE-13430
>             Project: HBase
>          Issue Type: Bug
>          Components: hbase
>            Reporter: Tobi Vollebregt
>            Priority: Critical
>              Labels: data-integrity, master
>             Fix For: 2.0.0, 1.0.1, 1.1.0, 0.98.13
>
>         Attachments: hbase-13430-attempted-fix.patch, hbase-13430-test.patch
>
>
> We recently had a production issue in which HFiles that were still in use by 
> a table were deleted. This appears to have been caused by race conditions in 
> the order in which HFileLinks are created, combined with the fact that only 
> files younger than {{hbase.master.hfilecleaner.ttl}} are kept alive.
> This is how to reproduce:
>  * Clone a large snapshot into a new table. The clone operation must take 
> more than {{hbase.master.hfilecleaner.ttl}} time to guarantee data loss.
>  * Ensure that no other table or snapshot is referencing the HFiles used by 
> the new table.
>  * Delete the snapshot. This breaks the table.
> The main cause is this:
>  * Cloning a snapshot creates the table in the {{HBASE_TEMP_DIRECTORY}}.
>  * However, it immediately creates back references to the HFileLinks that it 
> creates for the table in the archive directory.
>  * HFileLinkCleaner does not check the {{HBASE_TEMP_DIRECTORY}}, so it 
> considers all those back references deletable.
>  * The only thing that keeps them alive is the TimeToLiveHFileCleaner, but 
> only for 5 minutes.
>  * So if cloning the snapshot takes more than 5 minutes, and the HFiles 
> aren't referenced by anything else, data loss is guaranteed.
> I have a unit test reproducing the issue and I tried to fix this, but didn't 
> completely succeed. I will attach the patch shortly.
> Workarounds:
>  * Don't delete any snapshots that you cloned into a table (we used this 
> successfully-- we actually restored the deleted snapshot from backup using 
> ExportSnapshot after the data loss happened, which successfully reversed the 
> data loss).
>  * Manually check the back references and create any missing ones after 
> cloning a snapshot.
>  * Increase {{hbase.master.hfilecleaner.ttl}}. (untested)



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[jira] [Commented] (HBASE-13430) HFiles that are in use by a table cloned from a snapshot may be deleted when that snapshot is deleted

Reply via email to