[erlang-bugs] mnesia can corrupt tables if the VM runs out of file descriptors

[Mikael Pettersson]

Mikael Pettersson writes:
 > -module(mnesia_corrupts_data).
 > -compile(export_all).
 > 
 > -record(foo, {key, data}).
 > 
 > doit() ->
 >     %% set up initial db with foo.DCD and foo.DCL,
 >     %% foo contains records with keys [0,N[
 >     N = init_db(),
 >     io:format("Initial DB:\n~s", [os:cmd("ls -l Mnesia.nonode@REDACTED")]),
 >     FDs = open_all_available_fds(),
 >     %% free enough FDs so mnesia can start, but not enough for it
 >     %% to be able to open foo.DCL
 >     close_some_fds(FDs),
 >     check_db(N).
 > 
 > init_db() ->
 >     ok = mnesia:create_schema([node()]),
 >     ok = mnesia:start(),
 >     {atomic, ok} = mnesia:create_table(foo,
 > 				       [{attributes, record_info(fields, foo)},
 > 					{disc_copies, [node()]}]),
 >     N = create_dcl(0),
 >     stopped = mnesia:stop(),
 >     N.
 > 
 > create_dcl(N) ->
 >     case prim_file:read_file_info("Mnesia.nonode@REDACTED/foo.DCL") of
 > 	{error, enoent} ->
 > 	    {atomic, ok} =
 > 		mnesia:transaction(fun() -> mnesia:write(#foo{key = N, data = "bar"}) end),
 > 	    create_dcl(N + 1);
 > 	{ok, _} ->
 > 	    io:format("DCL created after ~p records written\n", [N]),
 > 	    N
 >     end.
 > 
 > check_db(N) ->
 >     ok = mnesia:start(),
 >     ok = mnesia:wait_for_tables([foo], 5*1000),
 >     check_foo(0, N).
 > 
 > check_foo(I, N) when I < N ->
 >     [{foo, I, "bar"}] = mnesia:dirty_read(foo, I),
 >     check_foo(I + 1, N);
 > check_foo(I, N) when I >= N ->
 >     ok.
 > 
 > open_all_available_fds() ->
 >     ok = file:write_file("dummy.txt", <<"whatever\n">>),
 >     open_all_available_fds([], 0).
 > 
 > open_all_available_fds(FDs, N) ->
 >     case prim_file:open("dummy.txt", [read]) of
 > 	{ok, FD} ->
 > 	    open_all_available_fds([FD | FDs], N + 1);
 > 	{error, emfile} ->
 > 	    io:format("managed to open ~p files\n", [N]),
 > 	    FDs
 >     end.
 > 
 > close_some_fds([FD1, FD2 | _]) ->
 >     prim_file:close(FD1),
 >     prim_file:close(FD2).
 > 
 > ----------------------------------------------------------------------
 > If the Erlang VM is close to its file descriptor limit, and mnesia tries
 > to open a disc_copies table's .DCL file, the open fails with {error, emfile}
 > which mnesia_log:open_log/6 incorrectly interprets as a corrupt file, and it
 > then DELETES the perfectly valid .DCL file.
 > 
 > This is reproducible with (at least) OTP 18.0-rc2 and R15B03.
 > 
 > (This is not a hypothetical problem, it hit us and corrupted three tables,
 > though we managed to recover through luck and manual emergency procedures.)
 > 
 > I'm attaching a standalone module which reproduces the corruption for me
 > with OTP 18.0-rc2 on a Fedora 20 Linux / x86_64 desktop system.  Here's a
 > transcript from a run of that module (foo.DCL is the interesting file):
 > 
 > Script started on Sat 30 May 2015 05:47:41 PM CEST
 > _1_/tmp/otp/bin/erlc mnesia_corrupts_data.erl
 > _2_/tmp/otp/bin/erl
 > Erlang/OTP 18 [RELEASE CANDIDATE 2] [erts-7.0] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false]
 > 
 > Eshell V7.0  (abort with ^G)
 > 1> mnesia_corrupts_data:doit().
 > DCL created after 1024 records written
 > 
 > =INFO REPORT==== 30-May-2015::17:48:23 ===
 >     application: mnesia
 >     exited: stopped
 >     type: temporary
 > Initial DB:
 > total 152
 > -rw-r--r-- 1 mikpe mikpe   2715 May 30 17:48 LATEST.LOG
 > -rw-r--r-- 1 mikpe mikpe 104101 May 30 17:48 PREVIOUS.LOG
 > -rw-r--r-- 1 mikpe mikpe      8 May 30 17:48 foo.DCD
 > -rw-r--r-- 1 mikpe mikpe  31039 May 30 17:48 foo.DCL
 > -rw-r--r-- 1 mikpe mikpe   6750 May 30 17:48 schema.DAT
 > managed to open 1014 files
 > Mnesia(nonode@REDACTED): Data may be missing, Corrupt logfile deleted: "/tmp/Mnesia.nonode@REDACTED/foo.DCL", {file_error,
 >                                                                                                            "/tmp/Mnesia.nonode@REDACTED/foo.DCL",
 >                                                                                                            emfile} 
 > 
 > =ERROR REPORT==== 30-May-2015::17:48:25 ===
 > Mnesia(nonode@REDACTED): ** ERROR ** (could not write core file: emfile)
 >  ** FATAL ** Cannot open log file "/tmp/Mnesia.nonode@REDACTED/foo.DCL": {file_error,
 >                                                                         "/tmp/Mnesia.nonode@REDACTED/foo.DCL",
 >                                                                         emfile}
 > 
 > =ERROR REPORT==== 30-May-2015::17:48:35 ===
 > ** Generic server mnesia_monitor terminating 
 > ** Last message in was {'EXIT',<0.95.0>,killed}
 > ** When Server state == {state,<0.95.0>,[],[],true,[],undefined,[],[]}
 > ** Reason for termination == 
 > ** killed
 > 
 > =ERROR REPORT==== 30-May-2015::17:48:35 ===
 > ** Generic server mnesia_recover terminating 
 > ** Last message in was {'EXIT',<0.95.0>,killed}
 > ** When Server state == {state,<0.95.0>,undefined,undefined,undefined,0,false,
 >                                true,[]}
 > ** Reason for termination == 
 > ** killed
 > 
 > =INFO REPORT==== 30-May-2015::17:48:35 ===
 >     application: mnesia
 >     exited: {killed,{mnesia_sup,start,[normal,[]]}}
 >     type: temporary
 > ** exception exit: {badmatch,{error,{killed,{mnesia_sup,start,[normal,[]]}}}}
 >      in function  mnesia_corrupts_data:check_db/1 (mnesia_corrupts_data.erl, line 39)
 > 2> 
 > BREAK: (a)bort (c)ontinue (p)roc info (i)nfo (l)oaded
 >        (v)ersion (k)ill (D)b-tables (d)istribution
 > ^C
 > _3_ls -l Mnesia.nonode@REDACTED/
 > total 120
 > -rw-r--r-- 1 mikpe mikpe   2715 May 30 17:48 LATEST.LOG
 > -rw-r--r-- 1 mikpe mikpe 104101 May 30 17:48 PREVIOUS.LOG
 > -rw-r--r-- 1 mikpe mikpe      8 May 30 17:48 foo.DCD
 > -rw-r--r-- 1 mikpe mikpe   6750 May 30 17:48 schema.DAT
 > _4_
 > 
 > /Mikael

https://github.com/erlang/otp/pull/752

Tested with 18.0-rc2 and 17.5.3.