mnesia can corrupt tables if the VM runs out of file descriptors

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@nohost): Data may be missing, Corrupt logfile deleted: "/tmp/Mnesia.nonode@nohost/foo.DCL", {file_error,
                                                                                                           "/tmp/Mnesia.nonode@nohost/foo.DCL",
                                                                                                           emfile} 

=ERROR REPORT==== 30-May-2015::17:48:25 ===
Mnesia(nonode@nohost): ** ERROR ** (could not write core file: emfile)
 ** FATAL ** Cannot open log file "/tmp/Mnesia.nonode@nohost/foo.DCL": {file_error,
                                                                        "/tmp/Mnesia.nonode@nohost/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@nohost/
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

_______________________________________________
erlang-bugs mailing list
[email protected]
http://erlang.org/mailman/listinfo/erlang-bugs

-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@nohost")]),
    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@nohost/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).