Master writing to bad metalog file

After a shutdown, upgrade and restart on a cluster running on HDFS, the master 
somehow ended up writing to a bad mml file.

[root@master1 sanjit]# hadoop fs -ls /hypertable/servers/master/log/mml|tail -n 
2
-rw-r--r--   3 root supergroup    4740887 2011-09-20 09:55 
/hypertable/servers/master/log/mml/93
-rw-r--r--   3 root supergroup      29531 2011-10-20 17:57 
/hypertable/servers/master/log/mml/94.bad

the length of the bad file matches the backup

[root@master1 ~]# ls -ltr 
/opt/hypertable/current/run/log_backup/mml/master_38050/|tail -n 2
-rw-r--r-- 1 root root 4740887 2011-10-14 07:10 93
-rw-r--r-- 1 root root   29531 2011-10-20 21:30 94

grepping the master (case insensitive) log for "bad" and "meta" yielded 
nothing. 
From the DfsBroker log it looks like the master opens the mml with handle=2, 
then reopens it with handle=3, renames using handle=3, keeps writing with 
handle=2.

From the log DfsBroker.log:

INFO: Testing for existence of file '/hypertable/servers/master/log/mml
20-Oct-2011 17:57:53 org.hypertable.DfsBroker.hadoop.HdfsBroker Readdir
INFO: Readdir('/hypertable/servers/master/log/mml')
20-Oct-2011 17:57:53 org.hypertable.DfsBroker.hadoop.HdfsBroker Remove
INFO: Removing file '/hypertable/servers/master/log/mml/83
20-Oct-2011 17:57:53 org.hypertable.DfsBroker.hadoop.HdfsBroker Create
INFO: Creating file '/hypertable/servers/master/log/mml/94' handle = 2
20-Oct-2011 17:57:53 org.hypertable.DfsBroker.hadoop.HdfsBroker Create
INFO: Created file '/hypertable/servers/master/log/mml/94' handle = 2
...
...
INFO: Testing for existence of file '/hypertable/servers/master/log/mml
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker Readdir
INFO: Readdir('/hypertable/servers/master/log/mml')
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker Length
INFO: Getting length of file '/hypertable/servers/master/log/mml/94
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker OpenINFO: 
Opening file '/hypertable/servers/master/log/mml/94' flags=0 bs=0 handle = 3
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker Close
INFO: Closing input file /hypertable/servers/master/log/mml/94 handle 3
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker Rename
INFO: Renaming /hypertable/servers/master/log/mml/94 -> 
/hypertable/servers/master/log/mml/94.bad
20-Oct-2011 19:31:28 org.hypertable.DfsBroker.hadoop.HdfsBroker Length
INFO: Getting length of file '/hypertable/servers/master/log/mml/93
....
....
during shutdown:
INFO: Closing output file /hypertable/servers/master/log/mml/94 handle 2
20-Oct-2011 21:31:15 org.hypertable.DfsBroker.hadoop.ConnectionHandler handle
INFO: [/127.0.0.1:60283 ; Thu Oct 20 21:31:15 BST 2011] Disconnect - COMM 
broken connection : Closin
g all open handles from /127.0.0.1:60283
Closed 0 input streams and 0 output streams for client connection 
/127.0.0.1:60283
20-Oct-2011 21:31:15 org.hypertable.DfsBroker.hadoop.HdfsBroker Close
SEVERE: I/O exception - org.apache.hadoop.ipc.RemoteException: 
org.apache.hadoop.hdfs.server.namenod
e.LeaseExpiredException: No lease on /hypertable/servers/master/log/mml/94 File 
does not exist. [Lea
se.  Holder: DFSClient_-756257359, pendingcreates: 1]
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:1542)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:1533)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFileInternal(FSNamesystem.jav
a:1588)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFile(FSNamesystem.java:1576)
        at org.apache.hadoop.hdfs.server.namenode.NameNode.complete(NameNode.java:671)
Original issue reported on code.google.com by sjha...@gmail.com on 20 Oct 2011 at 9:03
linearregression / hypertable

Master writing to bad metalog file #716
