HDFS, mail # user - Re: HDFS file disappeared

HDFS file disappeared

David Rosenstrauch 2010-11-11, 17:31

Had a really peculiar thing happen today: a file that a job of mine
created on HDFS seems to have disappeared, and I'm scratching my head as
to how this could have happened without any errors getting thrown.

I ran a M/R job that created a big bunch of files. Job completed
without errors, and it seems like file got created correctly. However
when another automated process went to use the file later, it failed
because the file wasn't there.

When I Sherlock Holmes my way through various log files, I see the
following:

1) M/R job task says that it successfully created the file:

2010-11-10 21:42:28,356 INFO <our package
name>.StateFileGeneratorOutputFormat: Data from partition #1 being
written to file hdfs://<our name node name>:9000<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state

2) Name node also says that it created the file:

[root@hdmaster hadoop-0.20]# grep 2010.11.10-21.05.29
hadoop-hadoop-namenode-hdmaster.log.2010-11-10 | grep
shard2/IntentTrait.state
2010-11-10 21:42:28,442 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our data node>
cmd=create src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
dst=null perm=root:supergroup:rw-r--r--
2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock: <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
blk_-4237880568969698703_13404582
2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
Removing lease on file <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
from client DFSClient_attempt_201010221550_0418_r_000001_0
2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
NameSystem.completeFile: file <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
is closed by DFSClient_attempt_201010221550_0418_r_000001_0

2a) Name node does *not* say in the logs anywhere that it deleted the
file. (i.e., the above 4 log lines are the only lines in the name node
log containing this file name)

3) Data node says that it created the file ...

[root@hddata09 hadoop-0.20]# grep 4237880568969698703_13404582
hadoop-hadoop-datanode-hddata09.log.2010-11-10
2010-11-10 21:42:29,827 INFO
org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block
blk_-4237880568969698703_13404582 src: /<our data node>:43883 dest:
/<our data node>:50010
2010-11-10 21:42:30,354 INFO
org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /<our
data node>:43883, dest: /<our data node>:50010, bytes: 326522, op:
HDFS_WRITE, cliID: DFSClient_attempt_201010221550_0418_r_000001_0,
offset: 0, srvID: DS-229869750-<our data node>-50010-1286316976632,
blockid: blk_-4237880568969698703_13404582, duration: 150566000
2010-11-10 21:42:30,354 INFO
org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 2 for
block blk_-4237880568969698703_13404582 terminating

4) ... but then it deletes it a few seconds later:

2010-11-10 21:42:34,831 INFO
org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block
blk_-4237880568969698703_13404582 file
/usr/local/hadoop/dfs/data/current/subdir36/subdir10/blk_-4237880568969698703
for deletion
2010-11-10 21:42:34,832 INFO
org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block
blk_-4237880568969698703_13404582 at file
/usr/local/hadoop/dfs/data/current/subdir36/subdir10/blk_-4237880568969698703
Note that a) no errors were thrown anywhere about this file or block,
and b) there's nothing in the name node log indicating that the file was
explicitly deleted.

I'm scratching my head as to how this could have happened. Anyone have
any ideas / further debugging suggestions?

Thanks,

DR

Re: HDFS file disappeared

David Rosenstrauch 2010-11-11, 17:38

On 11/11/2010 12:31 PM, David Rosenstrauch wrote:
> 2) Name node also says that it created the file:
>
> [root@hdmaster hadoop-0.20]# grep 2010.11.10-21.05.29
> hadoop-hadoop-namenode-hdmaster.log.2010-11-10 | grep
> shard2/IntentTrait.state
> 2010-11-10 21:42:28,442 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our data node>
> cmd=create src=<our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> dst=null perm=root:supergroup:rw-r--r--
> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.allocateBlock: <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
> blk_-4237880568969698703_13404582
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
> Removing lease on file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> from client DFSClient_attempt_201010221550_0418_r_000001_0
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
> NameSystem.completeFile: file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>
> 2a) Name node does *not* say in the logs anywhere that it deleted the
> file. (i.e., the above 4 log lines are the only lines in the name node
> log containing this file name)

Sorry, I stand corrected. When I grep the name node logs for the block
ID there are some additional lines:

[root@hdmaster hadoop-0.20]# grep 4237880568969698703_13404582
hadoop-hadoop-namenode-hdmaster.log.2010-11-10
2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock: <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
blk_-4237880568969698703_13404582
2010-11-10 21:42:30,355 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.169:50010
is added to blk_-4237880568969698703_13404582 size 326522
2010-11-10 21:42:30,356 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.173:50010
is added to blk_-4237880568969698703_13404582 size 326522
2010-11-10 21:42:30,357 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.176:50010
is added to blk_-4237880568969698703_13404582 size 326522
2010-11-10 21:42:33,585 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
ask <our ip prefix>.176:50010 to delete blk_-4237880568969698703_13404582
2010-11-10 21:42:42,598 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
ask <our ip prefix>.173:50010 to delete blk_719995703651674050_13393533
blk_2844104197159113873_13393516 blk_6711472063024831893_13393527
blk_240592081553699046_13393054 blk_6933038421638165347_13393232
blk_-1288897671244436593_13393351 blk_1408176921409258101_13393152
blk_-4237880568969698703_13404582 blk_-4188858742780299895_13393410
blk_-2670318277937301225_13393450 blk_-1858397614006984730_13393480
blk_6292330466651227068_13393505
2010-11-10 21:42:42,598 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
ask <our ip prefix>.169:50010 to delete blk_719995703651674050_13393533
blk_6711472063024831893_13393527 blk_-514463419649319075_13404582
blk_-1980639884885154260_13404582 blk_240592081553699046_13393054
blk_8520588884031249451_13393428 blk_-6620589068796293265_13393089
blk_6933038421638165347_13393232 blk_-1288897671244436593_13393351
blk_-3581082286710707012_13393556 blk_1408176921409258101_13393152
blk_-1858397614006984730_13393480 blk_6292330466651227068_13393505
blk_2844104197159113873_13393516 blk_-4237880568969698703_13404582
blk_-4188858742780299895_13393410 blk_-2670318277937301225_13393450
I'm still not clear why those deletes are happening though. Will read
through the logs again at those locations. But if anyone's got any
ideas, pls chime in.

DR

Re: HDFS file disappeared

Todd Lipcon 2010-11-11, 19:13

Given that it's an MR output, my guess is it got moved out of the temporary
directory when the job "Committed" and then was removed as another pass. I'd
grep for the containing directory name in the audit logs to see where it got
moved to and how it was eventually deleted.

Would be great if someone wrote some tools that, given a block ID, tracked
the life of the file that contained it (including renames of containing
dirs, etc). Shouldn't be too difficult.

-Todd

On Thu, Nov 11, 2010 at 9:38 AM, David Rosenstrauch <[EMAIL PROTECTED]>wrote:

> On 11/11/2010 12:31 PM, David Rosenstrauch wrote:
>
>> 2) Name node also says that it created the file:
>>
>> [root@hdmaster hadoop-0.20]# grep 2010.11.10-21.05.29
>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10 | grep
>> shard2/IntentTrait.state
>> 2010-11-10 21:42:28,442 INFO
>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
>> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our data node>
>> cmd=create src=<our root
>>
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> dst=null perm=root:supergroup:rw-r--r--
>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.allocateBlock: <our root
>>
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>> blk_-4237880568969698703_13404582
>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
>> Removing lease on file <our root
>>
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> from client DFSClient_attempt_201010221550_0418_r_000001_0
>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
>> NameSystem.completeFile: file <our root
>>
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>>
>> 2a) Name node does *not* say in the logs anywhere that it deleted the
>> file. (i.e., the above 4 log lines are the only lines in the name node
>> log containing this file name)
>>
>
> Sorry, I stand corrected. When I grep the name node logs for the block ID
> there are some additional lines:
>
> [root@hdmaster hadoop-0.20]# grep 4237880568969698703_13404582
> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>
> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.allocateBlock: <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
> blk_-4237880568969698703_13404582
> 2010-11-10 21:42:30,355 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.169:50010 is
> added to blk_-4237880568969698703_13404582 size 326522
> 2010-11-10 21:42:30,356 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.173:50010 is
> added to blk_-4237880568969698703_13404582 size 326522
> 2010-11-10 21:42:30,357 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated: <our ip prefix>.176:50010 is
> added to blk_-4237880568969698703_13404582 size 326522
> 2010-11-10 21:42:33,585 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask
> <our ip prefix>.176:50010 to delete blk_-4237880568969698703_13404582
> 2010-11-10 21:42:42,598 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask
> <our ip prefix>.173:50010 to delete blk_719995703651674050_13393533
> blk_2844104197159113873_13393516 blk_6711472063024831893_13393527
> blk_240592081553699046_13393054 blk_6933038421638165347_13393232
> blk_-1288897671244436593_13393351 blk_1408176921409258101_13393152
> blk_-4237880568969698703_13404582 blk_-4188858742780299895_13393410
> blk_-2670318277937301225_13393450 blk_-1858397614006984730_13393480
> blk_6292330466651227068_13393505
> 2010-11-10 21:42:42,598 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask

Todd Lipcon
Software Engineer, Cloudera

Re: HDFS file disappeared

David Rosenstrauch 2010-11-11, 22:10

Saw a couple more references to that block before the "to delete blk"
messages:

2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
invalidSet of <our ip prefix>.169:50010
2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
invalidSet of <our ip prefix>.173:50010
2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
invalidSet of <our ip prefix>.176:50010

Again, I'm not sure why this is happening though.
BTW, I appreciate your comments below (about it getting moved out of the
temp directory and then getting removed in another pass). But I grepped
the logs as you suggested, and I still don't see how it got moved/deleted:

[root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
hadoop-hadoop-namenode-hdmaster.log.2010-11-10
2010-11-10 21:42:28,442 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
cmd=create src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
dst=null perm=root:supergroup:rw-r--r--
2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock: <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
blk_-4237880568969698703_13404582
2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
Removing lease on file <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
from client DFSClient_attempt_201010221550_0418_r_000001_0
2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
NameSystem.completeFile: file <our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
is closed by DFSClient_attempt_201010221550_0418_r_000001_0
I have to say, I'm really quite stumped. Been looking at this all
afternoon, and I still have no idea how/why that file got purged. :-(

Thanks,

DR

On 11/11/2010 02:13 PM, Todd Lipcon wrote:
> Given that it's an MR output, my guess is it got moved out of the temporary
> directory when the job "Committed" and then was removed as another pass. I'd
> grep for the containing directory name in the audit logs to see where it got
> moved to and how it was eventually deleted.
>
> Would be great if someone wrote some tools that, given a block ID, tracked
> the life of the file that contained it (including renames of containing
> dirs, etc). Shouldn't be too difficult.
>
> -Todd
>
> On Thu, Nov 11, 2010 at 9:38 AM, David Rosenstrauch<[EMAIL PROTECTED]>wrote:
>> Sorry, I stand corrected. When I grep the name node logs for the block ID
>> there are some additional lines:
>>
>> [root@hdmaster hadoop-0.20]# grep 4237880568969698703_13404582
>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>>
>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.allocateBlock:<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>> blk_-4237880568969698703_13404582
>> 2010-11-10 21:42:30,355 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addStoredBlock: blockMap updated:<our ip prefix>.169:50010 is
>> added to blk_-4237880568969698703_13404582 size 326522
>> 2010-11-10 21:42:30,356 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addStoredBlock: blockMap updated:<our ip prefix>.173:50010 is
>> added to blk_-4237880568969698703_13404582 size 326522
>> 2010-11-10 21:42:30,357 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addStoredBlock: blockMap updated:<our ip prefix>.176:50010 is

Re: HDFS file disappeared

David Rosenstrauch 2010-11-11, 23:00

On 11/11/2010 05:10 PM, David Rosenstrauch wrote:
> Saw a couple more references to that block before the "to delete blk"
> messages:
>
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
> invalidSet of <our ip prefix>.169:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
> invalidSet of <our ip prefix>.173:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
> invalidSet of <our ip prefix>.176:50010
>
> Again, I'm not sure why this is happening though.

What do these mean?

DR

Re: HDFS file disappeared

Todd Lipcon 2010-11-12, 00:14

What's the last audit log entry prior to 2010-11-10 21:42:33,389?

-Todd

On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch <[EMAIL PROTECTED]>wrote:

> Saw a couple more references to that block before the "to delete blk"
> messages:
>
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
> of <our ip prefix>.169:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
> of <our ip prefix>.173:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
> of <our ip prefix>.176:50010
>
> Again, I'm not sure why this is happening though.
>
>
> BTW, I appreciate your comments below (about it getting moved out of the
> temp directory and then getting removed in another pass). But I grepped the
> logs as you suggested, and I still don't see how it got moved/deleted:
>
> [root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
> 2010-11-10 21:42:28,442 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
> cmd=create src=<our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> dst=null perm=root:supergroup:rw-r--r--
>
> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.allocateBlock: <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
> blk_-4237880568969698703_13404582
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: Removing
> lease on file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> from client DFSClient_attempt_201010221550_0418_r_000001_0
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
> NameSystem.completeFile: file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>
>
> I have to say, I'm really quite stumped. Been looking at this all
> afternoon, and I still have no idea how/why that file got purged. :-(
>
> Thanks,
>
> DR
>
>
> On 11/11/2010 02:13 PM, Todd Lipcon wrote:
>
>> Given that it's an MR output, my guess is it got moved out of the
>> temporary
>> directory when the job "Committed" and then was removed as another pass.
>> I'd
>> grep for the containing directory name in the audit logs to see where it
>> got
>> moved to and how it was eventually deleted.
>>
>> Would be great if someone wrote some tools that, given a block ID, tracked
>> the life of the file that contained it (including renames of containing
>> dirs, etc). Shouldn't be too difficult.
>>
>> -Todd
>>
>> On Thu, Nov 11, 2010 at 9:38 AM, David Rosenstrauch<[EMAIL PROTECTED]
>> >wrote:
>>
>>> Sorry, I stand corrected. When I grep the name node logs for the block
>>> ID
>>>
>>> there are some additional lines:
>>>
>>> [root@hdmaster hadoop-0.20]# grep 4237880568969698703_13404582
>>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>>>
>>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.allocateBlock:<our root
>>>
>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>>> blk_-4237880568969698703_13404582
>>> 2010-11-10 21:42:30,355 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.addStoredBlock: blockMap updated:<our ip prefix>.169:50010 is
>>> added to blk_-4237880568969698703_13404582 size 326522
>>> 2010-11-10 21:42:30,356 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.addStoredBlock: blockMap updated:<our ip prefix>.173:50010 is
Todd Lipcon
Software Engineer, Cloudera

Re: HDFS file disappeared

Jakob Homan 2010-11-12, 00:38

>Would be great if someone wrote some tools that, given a block ID, tracked
>the life of the file that contained it (including renames of containing
> dirs, etc). Shouldn't be too difficult.

There's a tool for this in MapRed's contrib section under
block_forensics. It was released in 21, I believe. It hasn't been kept
up to date though, so I'm not sure how functional it still is.
-Jakob

Todd Lipcon wrote:
> What's the last audit log entry prior to 2010-11-10 21:42:33,389?
>
> -Todd
>
> On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch <[EMAIL PROTECTED]
> <mailto:[EMAIL PROTECTED]>> wrote:
>
> Saw a couple more references to that block before the "to delete
> blk" messages:
>
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange:
> BLOCK* NameSystem.addToInvalidates: blk_-4237880568969698703 is
> added to invalidSet of <our ip prefix>.169:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange:
> BLOCK* NameSystem.addToInvalidates: blk_-4237880568969698703 is
> added to invalidSet of <our ip prefix>.173:50010
> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange:
> BLOCK* NameSystem.addToInvalidates: blk_-4237880568969698703 is
> added to invalidSet of <our ip prefix>.176:50010
>
> Again, I'm not sure why this is happening though.
>
>
> BTW, I appreciate your comments below (about it getting moved out of
> the temp directory and then getting removed in another pass). But I
> grepped the logs as you suggested, and I still don't see how it got
> moved/deleted:
>
> [root@hdmaster hadoop-0.20]# grep
> _attempt_201010221550_0418_r_000001_0
> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
> 2010-11-10 21:42:28,442 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip
> root>.176 cmd=create src=<our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> dst=null perm=root:supergroup:rw-r--r--
>
> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange:
> BLOCK* NameSystem.allocateBlock: <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
> blk_-4237880568969698703_13404582
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
> Removing lease on file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> from client DFSClient_attempt_201010221550_0418_r_000001_0
> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange:
> DIR* NameSystem.completeFile: file <our root
> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>
>
> I have to say, I'm really quite stumped. Been looking at this all
> afternoon, and I still have no idea how/why that file got purged. :-(
>
> Thanks,
>
> DR
>
>
> On 11/11/2010 02:13 PM, Todd Lipcon wrote:
>
> Given that it's an MR output, my guess is it got moved out of
> the temporary
> directory when the job "Committed" and then was removed as
> another pass. I'd
> grep for the containing directory name in the audit logs to see
> where it got
> moved to and how it was eventually deleted.
>
> Would be great if someone wrote some tools that, given a block
> ID, tracked
> the life of the file that contained it (including renames of
> containing
> dirs, etc). Shouldn't be too difficult.
>
> -Todd
>
> On Thu, Nov 11, 2010 at 9:38 AM, David
> Rosenstrauch<[EMAIL PROTECTED] <mailto:[EMAIL PROTECTED]>>wrote:
>
> Sorry, I stand corrected. When I grep the name node logs

Re: HDFS file disappeared

David Rosenstrauch 2010-11-18, 15:24

Sorry, just first had a moment to get back to this now.

??? Never heard of the "audit log" before, and I don't see any file
named like that in the hadoop logs directory on the name node. Can you
elaborate what the audit log is and/or where it might be found?

Thanks,

DR

On 11/11/2010 07:14 PM, Todd Lipcon wrote:
> What's the last audit log entry prior to 2010-11-10 21:42:33,389?
>
> -Todd
>
> On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch<[EMAIL PROTECTED]>wrote:
>
>> Saw a couple more references to that block before the "to delete blk"
>> messages:
>>
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.169:50010
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.173:50010
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.176:50010
>>
>> Again, I'm not sure why this is happening though.
>>
>>
>> BTW, I appreciate your comments below (about it getting moved out of the
>> temp directory and then getting removed in another pass). But I grepped the
>> logs as you suggested, and I still don't see how it got moved/deleted:
>>
>> [root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>> 2010-11-10 21:42:28,442 INFO
>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
>> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
>> cmd=create src=<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> dst=null perm=root:supergroup:rw-r--r--
>>
>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.allocateBlock:<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>> blk_-4237880568969698703_13404582
>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: Removing
>> lease on file<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> from client DFSClient_attempt_201010221550_0418_r_000001_0
>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
>> NameSystem.completeFile: file<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>>
>>
>> I have to say, I'm really quite stumped. Been looking at this all
>> afternoon, and I still have no idea how/why that file got purged. :-(
>>
>> Thanks,
>>
>> DR
>>
>>
>> On 11/11/2010 02:13 PM, Todd Lipcon wrote:
>>
>>> Given that it's an MR output, my guess is it got moved out of the
>>> temporary
>>> directory when the job "Committed" and then was removed as another pass.
>>> I'd
>>> grep for the containing directory name in the audit logs to see where it
>>> got
>>> moved to and how it was eventually deleted.
>>>
>>> Would be great if someone wrote some tools that, given a block ID, tracked
>>> the life of the file that contained it (including renames of containing
>>> dirs, etc). Shouldn't be too difficult.
>>>
>>> -Todd
>>>
>>> On Thu, Nov 11, 2010 at 9:38 AM, David Rosenstrauch<[EMAIL PROTECTED]
>>>> wrote:
>>>
>>>> Sorry, I stand corrected. When I grep the name node logs for the block
>>>> ID
>>>>
>>>> there are some additional lines:
>>>>
>>>> [root@hdmaster hadoop-0.20]# grep 4237880568969698703_13404582
>>>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>>>>
>>>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>>> NameSystem.allocateBlock:<our root
>>>>
>>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.

Re: HDFS file disappeared

Todd Lipcon 2010-11-18, 18:22

The "audit log" is a set of entries in the normal NN log by default. It can
be separated out into another log file if preferred, though it's not by
default.

Try grepping for "cmd=" in your NN log, you'll see what we're talking about.

-Todd

On Thu, Nov 18, 2010 at 7:24 AM, David Rosenstrauch <[EMAIL PROTECTED]>wrote:

> Sorry, just first had a moment to get back to this now.
>
> ??? Never heard of the "audit log" before, and I don't see any file named
> like that in the hadoop logs directory on the name node. Can you elaborate
> what the audit log is and/or where it might be found?
>
> Thanks,
>
> DR
>
>
> On 11/11/2010 07:14 PM, Todd Lipcon wrote:
>
>> What's the last audit log entry prior to 2010-11-10 21:42:33,389?
>>
>> -Todd
>>
>> On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch<[EMAIL PROTECTED]
>> >wrote:
>>
>> Saw a couple more references to that block before the "to delete blk"
>>> messages:
>>>
>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>> invalidSet
>>> of<our ip prefix>.169:50010
>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>> invalidSet
>>> of<our ip prefix>.173:50010
>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>> invalidSet
>>> of<our ip prefix>.176:50010
>>>
>>> Again, I'm not sure why this is happening though.
>>>
>>>
>>> BTW, I appreciate your comments below (about it getting moved out of the
>>> temp directory and then getting removed in another pass). But I grepped
>>> the
>>> logs as you suggested, and I still don't see how it got moved/deleted:
>>>
>>> [root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
>>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>>> 2010-11-10 21:42:28,442 INFO
>>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
>>> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
>>> cmd=create src=<our root
>>>
>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>> dst=null perm=root:supergroup:rw-r--r--
>>>
>>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>> NameSystem.allocateBlock:<our root
>>>
>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>>> blk_-4237880568969698703_13404582
>>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: Removing
>>> lease on file<our root
>>>
>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>> from client DFSClient_attempt_201010221550_0418_r_000001_0
>>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
>>> NameSystem.completeFile: file<our root
>>>
>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>>>
>>>
>>> I have to say, I'm really quite stumped. Been looking at this all
>>> afternoon, and I still have no idea how/why that file got purged. :-(
>>>
>>> Thanks,
>>>
>>> DR
>>>
>>>
>>> On 11/11/2010 02:13 PM, Todd Lipcon wrote:
>>>
>>> Given that it's an MR output, my guess is it got moved out of the
>>>> temporary
>>>> directory when the job "Committed" and then was removed as another pass.
>>>> I'd
>>>> grep for the containing directory name in the audit logs to see where it
>>>> got
>>>> moved to and how it was eventually deleted.
>>>>
>>>> Would be great if someone wrote some tools that, given a block ID,
>>>> tracked
>>>> the life of the file that contained it (including renames of containing
>>>> dirs, etc). Shouldn't be too difficult.
>>>>
>>>> -Todd
>>>>
>>>> On Thu, Nov 11, 2010 at 9:38 AM, David Rosenstrauch<[EMAIL PROTECTED]
Todd Lipcon
Software Engineer, Cloudera

Re: HDFS file disappeared

David Rosenstrauch 2010-11-18, 18:37

Tnx!

Checking the logs now ...

DR

On 11/18/2010 01:22 PM, Todd Lipcon wrote:
> The "audit log" is a set of entries in the normal NN log by default. It can
> be separated out into another log file if preferred, though it's not by
> default.
>
> Try grepping for "cmd=" in your NN log, you'll see what we're talking about.
>
> -Todd
>
> On Thu, Nov 18, 2010 at 7:24 AM, David Rosenstrauch<[EMAIL PROTECTED]>wrote:
>
>> Sorry, just first had a moment to get back to this now.
>>
>> ??? Never heard of the "audit log" before, and I don't see any file named
>> like that in the hadoop logs directory on the name node. Can you elaborate
>> what the audit log is and/or where it might be found?
>>
>> Thanks,
>>
>> DR
>>
>>
>> On 11/11/2010 07:14 PM, Todd Lipcon wrote:
>>
>>> What's the last audit log entry prior to 2010-11-10 21:42:33,389?
>>>
>>> -Todd
>>>
>>> On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch<[EMAIL PROTECTED]
>>>> wrote:
>>>
>>> Saw a couple more references to that block before the "to delete blk"
>>>> messages:
>>>>
>>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>>> invalidSet
>>>> of<our ip prefix>.169:50010
>>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>>> invalidSet
>>>> of<our ip prefix>.173:50010
>>>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to
>>>> invalidSet
>>>> of<our ip prefix>.176:50010
>>>>
>>>> Again, I'm not sure why this is happening though.
>>>>
>>>>
>>>> BTW, I appreciate your comments below (about it getting moved out of the
>>>> temp directory and then getting removed in another pass). But I grepped
>>>> the
>>>> logs as you suggested, and I still don't see how it got moved/deleted:
>>>>
>>>> [root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
>>>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>>>> 2010-11-10 21:42:28,442 INFO
>>>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
>>>> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
>>>> cmd=create src=<our root
>>>>
>>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>>> dst=null perm=root:supergroup:rw-r--r--
>>>>
>>>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>>>> NameSystem.allocateBlock:<our root
>>>>
>>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state.
>>>> blk_-4237880568969698703_13404582
>>>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: Removing
>>>> lease on file<our root
>>>>
>>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>>> from client DFSClient_attempt_201010221550_0418_r_000001_0
>>>> 2010-11-10 21:42:30,360 INFO org.apache.hadoop.hdfs.StateChange: DIR*
>>>> NameSystem.completeFile: file<our root
>>>>
>>>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>>>> is closed by DFSClient_attempt_201010221550_0418_r_000001_0
>>>>
>>>>
>>>> I have to say, I'm really quite stumped. Been looking at this all
>>>> afternoon, and I still have no idea how/why that file got purged. :-(
>>>>
>>>> Thanks,
>>>>
>>>> DR
>>>>
>>>>
>>>> On 11/11/2010 02:13 PM, Todd Lipcon wrote:
>>>>
>>>> Given that it's an MR output, my guess is it got moved out of the
>>>>> temporary
>>>>> directory when the job "Committed" and then was removed as another pass.
>>>>> I'd
>>>>> grep for the containing directory name in the audit logs to see where it
>>>>> got
>>>>> moved to and how it was eventually deleted.
>>>>>
>>>>> Would be great if someone wrote some tools that, given a block ID,
>>>>> tracked
>>>>> the life of the file that contained it (including renames of containing

Re: HDFS file disappeared

David Rosenstrauch 2010-11-18, 18:58

These are the audit log entries immediately preceding that timestamp:

2010-11-10 21:42:33,034 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=listStatus src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000000_0
   dst=null perm=null
2010-11-10 21:42:33,043 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=mkdirs src=<our root dir>/2010.11.10-21.05.29/output
dst=null perm=root:supergroup:rwxr-xr-x
2010-11-10 21:42:33,046 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=listStatus src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000000_0/shard1
   dst=null perm=null
2010-11-10 21:42:33,047 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=mkdirs src=<our root
dir>/2010.11.10-21.05.29/output/shard1 dst=null
perm=root:supergroup:rwxr-xr-x
2010-11-10 21:42:33,070 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=rename src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000000_0/shard1/IntentTrait.state
  dst=<our root dir>/2010.11.10-21.05.29/output/shard1/IntentTrait.state
   perm=root:supergroup:rw-r--r--
2010-11-10 21:42:33,093 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=delete src=<our root
dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000000_0
   dst=null perm=null
2010-11-10 21:42:33,341 INFO
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip prefix>.178
   cmd=open src=<our root dir>/conf/ShardingTable.txt
dst=null perm=null

Thanks,

DR

On 11/11/2010 07:14 PM, Todd Lipcon wrote:
> What's the last audit log entry prior to 2010-11-10 21:42:33,389?
>
> -Todd
>
> On Thu, Nov 11, 2010 at 2:10 PM, David Rosenstrauch<[EMAIL PROTECTED]>wrote:
>
>> Saw a couple more references to that block before the "to delete blk"
>> messages:
>>
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.169:50010
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.173:50010
>> 2010-11-10 21:42:33,389 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.addToInvalidates: blk_-4237880568969698703 is added to invalidSet
>> of<our ip prefix>.176:50010
>>
>> Again, I'm not sure why this is happening though.
>>
>>
>> BTW, I appreciate your comments below (about it getting moved out of the
>> temp directory and then getting removed in another pass). But I grepped the
>> logs as you suggested, and I still don't see how it got moved/deleted:
>>
>> [root@hdmaster hadoop-0.20]# grep _attempt_201010221550_0418_r_000001_0
>> hadoop-hadoop-namenode-hdmaster.log.2010-11-10
>> 2010-11-10 21:42:28,442 INFO
>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit:
>> ugi=root,root,bin,daemon,sys,adm,disk,wheel ip=/<our ip root>.176
>> cmd=create src=<our root
>> dir>/2010.11.10-21.05.29/output/_temporary/_attempt_201010221550_0418_r_000001_0/shard2/IntentTrait.state
>> dst=null perm=root:supergroup:rw-r--r--
>>
>> 2010-11-10 21:42:29,802 INFO org.apache.hadoop.hdfs.StateChange: BLOCK*
>> NameSystem.allocateBlock:<our root