Add random-netsplits tc, trace improvements

include/locks_trace.hrl

@@ -0,0 +1,10 @@
+%% This is to support stack traces on pre-OTP21 versions
+%% while avoiding compiler warnings on later versions.
+-ifdef(OTP_RELEASE).
+-define(_catch_(ErrorType, Error, ErrorStackTrace),
+        catch ErrorType:Error:ErrorStackTrace ->).
+-else.
+-define(_catch_(ErrorType, Error, ErrorStackTrace),
+        catch ErrorType:Error ->
+            ErrorStackTrace = erlang:get_stacktrace(),).
+-endif.

rebar.config

@@ -27,5 +27,10 @@
                                  {top_level_readme,
                                   {"./README.md","https://github.com/uwiger/locks"}}]}
                    ]},
-            {test, [{project_app_dirs, [".", "examples/gdict"]}]}
+            {test, [ {project_app_dirs, [".", "examples/gdict"]}
+                   , {deps, [{leader, ".*",
+                              {git, "https://github.com/uwiger/locks-test.git",
+                               {branch, "uw-error-inspection"}}}
+                            ]}
+                   ]}
            ]}.

rebar.lock

@@ -1,6 +1,8 @@
-{"1.1.0",
+{"1.2.0",
 [{<<"plain_fsm">>,{pkg,<<"plain_fsm">>,<<"1.4.1">>},0}]}.
 [
 {pkg_hash,[
- {<<"plain_fsm">>, <<"47E9BF6AC9322FC7586FB6DF8DE7198391E93764571C75165F2C45B27ACDE1D0">>}]}
+ {<<"plain_fsm">>, <<"47E9BF6AC9322FC7586FB6DF8DE7198391E93764571C75165F2C45B27ACDE1D0">>}]},
+{pkg_hash_ext,[
+ {<<"plain_fsm">>, <<"6CE2E7EFDCDC516EEBCED22A6ED2B1AB760F8275EE230F7C80B48DD32AE0DA39">>}]}
 ].

src/locks_agent.erl

@@ -58,6 +58,7 @@
 
 -import(lists,[foreach/2,any/2,map/2,member/2]).
 
+-include("locks_trace.hrl").
 -include("locks_agent.hrl").
 
 -ifdef(DEBUG).
@@ -173,12 +174,11 @@ agent_init(Wait, Client, Options) ->
         {ok, St} ->
             ack(Wait, Client, {ok, self()}),
             try loop(St)
-            catch
-                error:Error ->
+            ?_catch_(error, Error, ST)
                     error_logger:error_report(
                       [{?MODULE, aborted},
                        {reason, Error},
-                       {trace, erlang:get_stacktrace()}]),
+                       {trace, ST}]),
                     error(Error)
             end
         %% Other ->

src/locks_leader.erl

@@ -135,13 +135,14 @@
 	  mod_state,
 	  buffered = []}).
 
+-include("locks_trace.hrl").
 -include("locks.hrl").
 -include("locks_debug.hrl").
 
 -ifdef(LOCKS_DEBUG).
 -define(log(X, S), dbg_log(X, S)).
 -else.
--define(log(X, S), ok).
+-define(log(X, S), ?event(X, S)).
 -endif.
 
 -define(event(E), event(?LINE, E, none)).
@@ -460,9 +461,8 @@ init_(Module, ModSt0, Options, Parent, Reg) ->
 		{ok, MSt} -> MSt;
 		{error, Reason} ->
 		    abort_init(Reason, Parent)
-	    catch
-		error:Error ->
-		    abort_init({Error, erlang:get_stacktrace()}, Parent)
+	    ?_catch_(error, Error, ST)
+		    abort_init({Error, ST}, Parent)
 	    end,
     AllNodes = ordsets:from_list([node()|nodes()]),
     Agent =
@@ -565,10 +565,10 @@ safe_loop(#st{agent = A} = S) ->
             ?log(_Msg, S),
             ?event({in_safe_loop, _Msg}, S),
             noreply(leader_affirmed(L, Ref, S));
-        {?MODULE, ensure_sync, _, _} = _Msg ->
+        {?MODULE, ensure_sync, L, Type, ERef} = _Msg ->
             ?log(_Msg, S),
             ?event({in_safe_loop, _Msg}, S),
-            noreply(S);
+            noreply(sync_requested(L, Type, ERef, S));
         {'$gen_call', From, '$locks_leader_debug'} = _Msg ->
             ?log(_Msg, S),
             handle_call('$locks_leader_debug', From, S);
@@ -641,11 +641,11 @@ handle_info_({?MODULE, leader_uncertain, L, Synced, SyncedWs}, S) ->
 handle_info_({?MODULE, affirm_leader, L, ERef} = _Msg, #st{} = S) ->
     ?event(_Msg, S),
     noreply(leader_affirmed(L, ERef, S));
-handle_info_({?MODULE, ensure_sync, Pid, Type} = _Msg, #st{} = S) ->
+handle_info_({?MODULE, ensure_sync, Pid, Type, _ERef} = _Msg, #st{} = S) ->
     ?event(_Msg, S),
     S1 = case S#st.leader of
              Me when Me == self() ->
-                 maybe_announce_leader(Pid, Type, remove_synced(Pid, Type, S));
+                 do_ensure_sync(Pid, Type, S);
              _ ->
                  S
          end,
@@ -832,6 +832,7 @@ add_cand(Client, S) when Client == self() ->
 add_cand(Client, #st{candidates = Cands, role = Role} = S) ->
     case lists:member(Client, Cands) of
 	false ->
+            ?event({add_cand, Client}),
             monitor_cand(Client),
             S1 = S#st{candidates = [Client | Cands]},
 	    if Role == worker ->
@@ -1089,9 +1090,28 @@ leader_affirmed(L, ERef, #st{} = S) ->
     request_sync(L, ERef, S).
 
 request_sync(L, ERef, S) ->
-    snd(L, {?MODULE, ensure_sync, self(), S#st.role}),
+    snd(L, {?MODULE, ensure_sync, self(), S#st.role, ERef}),
     S#st{leader = undefined, election_ref = ERef}.
 
+sync_requested(Pid, Type, ERef, #st{ leader = undefined
+                                   , election_ref = ERef
+                                   , vector = #{leader := Me}
+                                   , agent = A } = S)
+  when Me == self() ->
+    %% We were uncertain about whether we're leader, but this is
+    %% affirmation from at least one other candidate.
+    case locks_agent:transaction_status(A) of
+        {have_all_locks, _} ->
+            do_ensure_sync(Pid, Type, S#st{leader = self()});
+        _ ->
+            S
+    end;
+sync_requested(_, _, _, S) ->
+    S.
+
+do_ensure_sync(Pid, Type, S) ->
+    maybe_announce_leader(Pid, Type, remove_synced(Pid, Type, S)).
+
 set_leader_uncertain(#st{agent = A} = S) ->
     send_all(S, {?MODULE, leader_uncertain, self(),
                  S#st.synced, S#st.synced_workers}),
@@ -1151,5 +1171,6 @@ lock_holder(#lock{queue = [#w{entries = [#entry{agent = A}]}|_]}) ->
 
 -ifdef(LOCKS_DEBUG).
 dbg_log(X, #st{leader = L, vector = V}) ->
+    ?event(X, S),
     ?log(#{x => X, l => L, v => V}).
 -endif.

src/locks_ttb.erl

@@ -3,6 +3,11 @@
 -compile([export_all, nowarn_export_all]).
 -dialyzer({nowarn_function, pp_term/1}).
 
+-record(h1, { tab = ets:new(h1, [ordered_set])
+            , n   = 1
+            , max = 1000
+            , first_ts }).
+
 %% This function is also traced. Can be used to insert markers in the trace
 %% log.
 event(E) ->
@@ -37,15 +42,88 @@ format(Dir) ->
     format(Dir, standard_io).
 
 format(Dir, OutFile) ->
-    ttb:format(Dir, format_opts(OutFile)).
+    %% ttb:format(Dir, format_opts(OutFile)).
+    #h1{tab = T} = H1 = #h1{},
+    ok = ttb:format(Dir, [{handler, {fun handler1/4, H1}}]),
+    TS = fetch_ts(T),
+    PMap = fetch_pmap(T),
+    try to_file(OutFile, TS, PMap, T)
+    after
+        ets:delete(T)
+    end.
 
 format_opts() ->
     format_opts(standard_io).
 
 format_opts(OutFile) ->
     [{out, OutFile}, {handler, {fun handler/4, {0,0}}}].
 
-handler(Fd, Trace, _, {Tp,Diff} = Acc) ->
+to_file(OutFile, TS0, PMap, Tab) ->
+    {ok, Fd} = file:open(OutFile, [write]),
+    if TS0 > 0 ->
+            io:fwrite(Fd, "%% -*- erlang -*-~n", []);
+       true ->
+            ok
+    end,
+    try
+        ets:foldl(
+          fun({_, {Trace, TraceInfo}}, Acc) ->
+                  handler(Fd, Trace, TraceInfo, Acc)
+          end, {TS0,0,PMap}, Tab)
+    after
+        file:close(Fd)
+    end.
+
+handler1(_Fd, Trace, TraceInfo, #h1{ first_ts = undefined } = S)
+  when element(1, Trace) == trace_ts ->
+    log_ts(Trace, S),
+    log_pids(Trace, S),
+    log({Trace, TraceInfo}, S#h1{ first_ts = Trace });
+handler1(_Fd, Trace, TraceInfo, S) ->
+    log_pids(Trace, S),
+    log({Trace, TraceInfo}, S).
+
+log_ts(TraceTs, #h1{ tab = T }) ->
+    TS = element(tuple_size(TraceTs), TraceTs),
+    ets:insert(T, {ts, TS}).
+
+log_pids(Trace, #h1{ tab = T }) ->
+    PMap = get_pmap(T),
+    PMap1 = get_pids(Trace, #{}, ttb),
+    ets:insert(T, {pmap, maps:merge(PMap, PMap1)}).
+
+get_pmap(T) ->
+    case ets:lookup(T, pmap) of
+        [] ->
+            #{};
+        [{_, M}] ->
+            M
+    end.
+
+fetch_pmap(T) ->
+    M = get_pmap(T),
+    ets:delete(T, pmap),
+    M.
+
+fetch_ts(T) ->
+    case ets:lookup(T, ts) of
+        [] ->
+            0;
+        [{_, TS}] ->
+            ets:delete(T, ts),
+            TS
+    end.
+
+log(X, #h1{ tab = T, n = N, max = Max } = S) ->
+    ets:insert(T, {N, X}),
+    if N > Max ->
+            ets:delete(T, ets:first(T));
+       true ->
+            ok
+    end,
+    S#h1{ n = N+1 }.
+
+handler(Fd, Trace, _, {Tp,Diff,PMap} = Acc) ->
     if Acc == {0,0} ->
 	    io:fwrite(Fd, "%% -*- erlang -*-~n", []);
        true -> ok
@@ -57,15 +135,18 @@ handler(Fd, Trace, _, {Tp,Diff} = Acc) ->
 	    Tdiff = tdiff(TS, Tp),
 	    Diff1 = Diff + Tdiff,
 	    print(Fd, Node, Mod, Line, Evt, State, Diff1),
-	    case get_pids({Evt, State}) of
-		[] -> ok;
+	    case get_pids({Evt, State}, PMap) of
+		M when map_size(M) == 0 -> ok;
 		Pids ->
-		    io:fwrite(Fd, "    Nodes = ~p~n", [Pids])
+                    Nodes = [{node_prefix(P), N}
+                             || {P, N} <- lists:ukeysort(
+                                            2, maps:to_list(Pids))],
+		    io:fwrite(Fd, "    Nodes = ~p~n", [Nodes])
 	    end,
-	    {TS, Diff1};
+	    {TS, Diff1,PMap};
 	_ ->
 	    io:fwrite(Fd, "~p~n", [Trace]),
-	    {Tp, Diff}
+	    {Tp, Diff,PMap}
     end.
 
 -define(CHAR_MAX, 60).
@@ -127,29 +208,42 @@ record_print_fun(Mod) ->
 	    end
     end.
 
-get_pids(Term) ->
-    Pids = dict:to_list(get_pids(Term, dict:new())),
-    [{node_prefix(P), N} || {N, P} <- Pids].
+get_pids(Term, Ref) ->
+    get_pids(Term, #{}, Ref).
 
-get_pids(T, Acc) when is_tuple(T) ->
-    get_pids(tuple_to_list(T), Acc);
-get_pids(L, Acc) when is_list(L) ->
-    get_pids_(L, Acc);
-get_pids(P, Acc) when is_pid(P) ->
-    try ets:lookup(ttb, P) of
-	[{_, _, Node}] ->
-	    dict:store(Node, P, Acc);
+%% get_pids(Term, M) ->
+%%     get_pids(Term, Dict)),
+%%     [{node_prefix(P), N} || {N, P} <- Pids].
+
+get_pids(T, Acc, Ref) when is_tuple(T) ->
+    get_pids(tuple_to_list(T), Acc, Ref);
+get_pids(L, Acc, Ref) when is_list(L) ->
+    get_pids_(L, Acc, Ref);
+get_pids(P, Acc, Ref) when is_pid(P) ->
+    case check_ref(P, Ref) of
+        {ok, N} ->
+                    Acc#{P => N};
 	_ ->
 	    Acc
-    catch
-	error:_ -> Acc
     end;
-get_pids(_, Acc) ->
+get_pids(_, Acc, _) ->
     Acc.
 
-get_pids_([H|T], Acc) ->
-    get_pids_(T, get_pids(H, Acc));
-get_pids_(_, Acc) ->
+check_ref(P, ttb) ->
+    try ets:lookup(ttb, P) of
+        [{_, _, Node}] ->
+            {ok, Node};
+        _ ->
+            error
+    catch
+        error:_ -> error
+    end;
+check_ref(P, Map) when is_map(Map) ->
+    maps:find(P, Map).
+
+get_pids_([H|T], Acc, Ref) ->
+    get_pids_(T, get_pids(H, Acc, Ref), Ref);
+get_pids_(_, Acc, _) ->
     Acc.