hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Tobi Vollebregt (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-13430) HFiles that are in use by a table cloned from a snapshot may be deleted when that snapshot is deleted
Date Thu, 09 Apr 2015 18:20:14 GMT

    [ 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)

Mime
View raw message