2009-11-12 18:12:15,405 [IPC Server handler 10 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=52600, write=TestTable/TestTable,,1258049517024/52602
2009-11-12 18:12:15,407 [IPC Server handler 13 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=52700, write=TestTable/TestTable,,1258049517024/52702
2009-11-12 18:12:15,492 [regionserver/208.76.44.140:60020.logRoller] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049467300, entries=52741, calcsize=63761175, filesize=58592870. New hlog /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483
2009-11-12 18:12:15,494 [regionserver/208.76.44.140:60020.logRoller] DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 0 hlogs to remove  out of total 1; oldest outstanding seqnum is 1 from region .META.,,1
2009-11-12 18:12:15,494 [regionserver/208.76.44.140:60020.logSyncer] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: sync
2009-11-12 18:12:15,528 [IPC Server handler 13 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=0, write=TestTable/TestTable,,1258049517024/52746
.....

2009-11-12 18:12:19,578 [IPC Server handler 15 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=60700, write=TestTable/TestTable,,1258049517024/113447
2009-11-12 18:12:19,580 [IPC Server handler 15 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=60800, write=TestTable/TestTable,,1258049517024/113547
2009-11-12 18:12:19,584 [IPC Server handler 15 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=60900, write=TestTable/TestTable,,1258049517024/113647
2009-11-12 18:12:19,586 [IPC Server handler 15 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=61000, write=TestTable/TestTable,,1258049517024/113747
2009-11-12 18:12:19,589 [IPC Server handler 15 on 60020] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: edit=61100, write=TestTable/TestTable,,1258049517024/113847
2009-11-12 18:12:19,589 [regionserver/208.76.44.140:60020.logSyncer] INFO org.apache.hadoop.hbase.regionserver.wal.HLog: sync
2009-11-12 18:12:19,755 [regionserver/208.76.44.140:60020.cacheFlusher] DEBUG org.apache.hadoop.hbase.regionserver.Store: Added hdfs://aa0-000-12.u.powerset.com:9002/hbase/TestTable/1234347014/info/2510658122309964571, entries=60760, sequenceid=60764, memsize=67.2m, filesize=60.2m to TestTable,,1258049517024
2009-11-12 18:12:19,782 [regionserver/208.76.44.140:60020.cacheFlusher] DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~67.2m for region TestTable,,1258049517024 in 3777ms, sequence id=60764, compaction requested=false
2009-11-12 18:12:19,917 [regionserver/208.76.44.140:60020.logRoller] FATAL org.apache.hadoop.hbase.regionserver.LogRoller: Log rolling failed with ioe:
java.io.IOException: java.io.IOException: Cannot complete block: block has not been COMMITTED by the client
    at org.apache.hadoop.hdfs.server.namenode.BlockInfoUnderConstruction.convertToCompleteBlock(BlockInfoUnderConstruction.java:158)
    at org.apache.hadoop.hdfs.server.namenode.BlockManager.completeBlock(BlockManager.java:288)
    at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.finalizeINodeFileUnderConstruction(FSNamesystem.java:1846)
    at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFileInternal(FSNamesystem.java:1367)
    at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFile(FSNamesystem.java:1329)
    at org.apache.hadoop.hdfs.server.namenode.NameNode.complete(NameNode.java:660)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:516)
    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:964)
    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:960)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:396)
    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:958)

    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
    at org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(RemoteExceptionHandler.java:94)
    at org.apache.hadoop.hbase.RemoteExceptionHandler.checkThrowable(RemoteExceptionHandler.java:48)
    at org.apache.hadoop.hbase.RemoteExceptionHandler.checkIOException(RemoteExceptionHandler.java:66)
    at org.apache.hadoop.hbase.regionserver.LogRoller.run(LogRoller.java:98)



NN file history

[stack@aa0-000-12 logs]$ grep hlog.dat.1258049535483 hadoop-stack-namenode-aa0-000-12.u.powerset.com.log 
2009-11-12 18:12:15,486 DEBUG org.apache.hadoop.hdfs.StateChange: *DIR* NameNode.create: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995 at 208.76.44.140
2009-11-12 18:12:15,487 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile: src=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483, holder=DFSClient_984022995, clientMachine=208.76.44.140, createParent=true, replication=3, overwrite=true, append=false
2009-11-12 18:12:15,488 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.addFile: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 is added to the file system
2009-11-12 18:12:15,488 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile: add /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 to namespace for DFSClient_984022995
2009-11-12 18:12:15,489 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=stack,powerset,engineering  ip=/208.76.44.140       cmd=create      src=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483   dst=null        perm=stack:supergroup:rw-r--r--
2009-11-12 18:12:15,496 DEBUG org.apache.hadoop.hdfs.StateChange: *BLOCK* NameNode.addBlock: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:15,496 DEBUG org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.getAdditionalBlock: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:15,497 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.addFile: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 with blk_-6701182023950177090_1017 block is added to the in-memory file system
2009-11-12 18:12:15,497 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483. blk_-6701182023950177090_1017{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.142:51010|RBW]]}
2009-11-12 18:12:15,516 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.fsync: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:15,526 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.persistBlocks: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 with 1 blocks is persisted to the file system
2009-11-12 18:12:19,622 DEBUG org.apache.hadoop.hdfs.StateChange: *BLOCK* NameNode.addBlock: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:19,622 DEBUG org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.getAdditionalBlock: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:19,623 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.addFile: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 with blk_1566385428527738884_1018 block is added to the in-memory file system
2009-11-12 18:12:19,623 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483. blk_1566385428527738884_1018{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}
2009-11-12 18:12:19,780 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.fsync: file /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:19,780 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.persistBlocks: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 with 2 blocks is persisted to the file system
2009-11-12 18:12:19,838 DEBUG org.apache.hadoop.hdfs.StateChange: *DIR* NameNode.complete: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:19,839 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 for DFSClient_984022995
2009-11-12 18:12:19,840 INFO org.apache.hadoop.ipc.Server: IPC Server handler 6 on 9002, call complete(/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483, DFSClient_984022995, blk_1566385428527738884_1018) from 208.76.44.140:36475: error: java.io.IOException: Cannot complete block: block has not been COMMITTED by the client
2009-11-12 18:12:29,695 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=stack,powerset,engineering  ip=/208.76.44.139       cmd=open        src=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483   dst=null        perm=null
2009-11-12 18:12:30,989 DEBUG org.apache.hadoop.hdfs.StateChange: *DIR* Namenode.delete: src=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483, recursive=true
2009-11-12 18:12:30,990 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.delete: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483
2009-11-12 18:12:30,990 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.delete: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483
2009-11-12 18:12:30,990 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.unprotectedDelete: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 is removed
2009-11-12 18:12:30,990 DEBUG org.apache.hadoop.hdfs.server.namenode.LeaseManager: LeaseManager.findLease: prefix=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483
2009-11-12 18:12:30,999 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* Namesystem.delete: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 is removed
2009-11-12 18:12:31,000 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=stack,powerset,engineering  ip=/208.76.44.139       cmd=delete      src=/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483   dst=null        perm=null



NN block history


[stack@aa0-000-12 logs]$ grep blk_1566385428527738884_1018 hadoop-stack-namenode-aa0-000-12.u.powerset.com.log 
2009-11-12 18:12:19,623 DEBUG org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.addFile: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483 with blk_1566385428527738884_1018 block is added to the in-memory file system
2009-11-12 18:12:19,623 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483. blk_1566385428527738884_1018{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}
2009-11-12 18:12:19,832 DEBUG org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.blockReceived: blk_1566385428527738884_1018 is received from 208.76.44.141:51010
2009-11-12 18:12:19,832 DEBUG org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Reported block blk_1566385428527738884_1018 on 208.76.44.141:51010 size 785772 replicaState = FINALIZED
2009-11-12 18:12:19,832 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 208.76.44.141:51010 is added to blk_1566385428527738884_1018{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]} size 785772
2009-11-12 18:12:19,835 DEBUG org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.blockReceived: blk_1566385428527738884_1018 is received from 208.76.44.139:51010
2009-11-12 18:12:19,835 DEBUG org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Reported block blk_1566385428527738884_1018 on 208.76.44.139:51010 size 785772 replicaState = FINALIZED
2009-11-12 18:12:19,836 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 208.76.44.139:51010 is added to blk_1566385428527738884_1018{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]} size 785772
2009-11-12 18:12:19,836 DEBUG org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.blockReceived: blk_1566385428527738884_1018 is received from 208.76.44.140:51010
2009-11-12 18:12:19,836 DEBUG org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Reported block blk_1566385428527738884_1018 on 208.76.44.140:51010 size 785772 replicaState = FINALIZED
2009-11-12 18:12:19,836 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 208.76.44.140:51010 is added to blk_1566385428527738884_1018{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]} size 785772
2009-11-12 18:12:19,840 INFO org.apache.hadoop.ipc.Server: IPC Server handler 6 on 9002, call complete(/hbase/.logs/aa0-000-13.u.powerset.com,60020,1258049466956/hlog.dat.1258049535483, DFSClient_984022995, blk_1566385428527738884_1018) from 208.76.44.140:36475: error: java.io.IOException: Cannot complete block: block has not been COMMITTED by the client
2009-11-12 18:12:29,695 DEBUG org.apache.hadoop.hdfs.server.namenode.FSNamesystem: blocks = [blk_-6701182023950177090_1017{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.142:51010|RBW]]}, blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}]
2009-11-12 18:12:29,695 DEBUG org.apache.hadoop.hdfs.server.namenode.FSNamesystem: last = blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}
2009-11-12 18:12:30,990 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]} to 208.76.44.141:51010 208.76.44.139:51010 208.76.44.140:51010 
2009-11-12 18:12:33,568 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 208.76.44.140:51010 to delete  blk_-6701182023950177090_1017{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.142:51010|RBW]]} blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}
2009-11-12 18:12:33,569 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 208.76.44.139:51010 to delete  blk_-6701182023950177090_1017{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.142:51010|RBW]]} blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]} blk_7151529243582448726_1012
2009-11-12 18:12:36,578 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 208.76.44.141:51010 to delete  blk_1566385428527738884_1018{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[208.76.44.140:51010|RBW], ReplicaUnderConstruction[208.76.44.139:51010|RBW], ReplicaUnderConstruction[208.76.44.141:51010|RBW]]}