diff options
Diffstat (limited to 'lib/kernel/test/global_SUITE_data')
| -rw-r--r-- | lib/kernel/test/global_SUITE_data/global_trace.erl | 1023 |
1 files changed, 1023 insertions, 0 deletions
diff --git a/lib/kernel/test/global_SUITE_data/global_trace.erl b/lib/kernel/test/global_SUITE_data/global_trace.erl new file mode 100644 index 0000000000..4f253baac4 --- /dev/null +++ b/lib/kernel/test/global_SUITE_data/global_trace.erl @@ -0,0 +1,1023 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2007-2009. All Rights Reserved. +%% +%% The contents of this file are subject to the Erlang Public License, +%% Version 1.1, (the "License"); you may not use this file except in +%% compliance with the License. You should have received a copy of the +%% Erlang Public License along with this software. If not, it can be +%% retrieved online at http://www.erlang.org/. +%% +%% Software distributed under the License is distributed on an "AS IS" +%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See +%% the License for the specific language governing rights and limitations +%% under the License. +%% +%% %CopyrightEnd% +%% +-module(global_trace). + +%%% +%%% Inspection of High Level Trace created by global.erl. +%%% + +%%% A few handy functions when running the test_server +%%% + +d() -> + lists:foreach(fun(F) -> dd(F, []) end, last()). + +d(Testcase) -> + d(Testcase, []). + +%% Skip "global_" from T. +d(Testcase, Options) -> + [Filename] = tmp_files(Testcase), + dd(Filename, Options). + +dd(Filename, Options) -> + io:format("\n======= ~s \n", [Filename]), + t(Filename, Options). + +last() -> + tmp_files("*"). + +%% global_groups_change: one node is restarted +%% global_mass_death: nodes are stopped +%% global_lock_die: two spurious (trying to remove locks taken by other pid) +%% global_otp_5640: 4 spurious (names registered again &c) +tmp_files(A) when is_atom(A) -> + tmp_files(atom_to_list(A)); +tmp_files(T) when is_list(T) -> + Logs = logdir(), + Dir = lists:last(filelib:wildcard(filename:join(Logs, "*"))), + filelib:wildcard(filename:join([Dir, log_private, "global_" ++ T])). + +%logdir() -> +% "/net/yoshi/ldisk/daily_build/otp_norel_linux_r11b.2007-02-18_19/" +% "test/test_server/global_SUITE.logs"; +%logdir() -> +% "/ldisk/daily_build/otp_norel_linux_suse_r11b.2007-02-07_19/test/" +% "test_server/global_SUITE.logs"; +logdir() -> + "/tmp/tests/test_server/global_SUITE.logs". + + + +%%% The contents of this file is by no means fixed; the printouts are +%%% updated depending on the problems at hand. Not everything has been +%%% designed very carefully :) +%%% +%%% For one thing, the trace from all nodes are written onto the file +%%% as one single term. One term per node would be better. &c. + +-compile(export_all). + +-record(state, {connect_all, known = [], synced = [], + resolvers = [], syncers = [], node_name = node(), + the_locker, the_deleter, the_registrar, trace = [], + global_lock_down + }). + +%% Compatible with different versions. +state(#state{}=S) -> + S; +state({state, ConnectAll, Known, Synced, LockersResolvers, Syncers, + NodeName, TheLocker, TheDeleter}) -> + %% r10b: Lockers, r10b_patched, r11b: Resolvers + #state{connect_all = ConnectAll, known = Known, synced = Synced, + resolvers = LockersResolvers, syncers = Syncers, + node_name = NodeName, the_locker = TheLocker, + the_deleter = TheDeleter, the_registrar = undefined, trace = []}; +state({state, ConnectAll, Known, Synced, Resolvers, Syncers, + NodeName, TheLocker, TheDeleter, Trace}) -> + %% r11b, some time before r11b-3 + #state{connect_all = ConnectAll, known = Known, synced = Synced, + resolvers = Resolvers, syncers = Syncers, + node_name = NodeName, the_locker = TheLocker, + the_deleter = TheDeleter, the_registrar = undefined, + trace = Trace}; +state({state, ConnectAll, Known, Synced, Resolvers, Syncers, + NodeName, TheLocker, TheDeleter, TheRegistrar, Trace}) -> + %% r11b, some time after r11b-3 + #state{connect_all = ConnectAll, known = Known, synced = Synced, + resolvers = Resolvers, syncers = Syncers, + node_name = NodeName, the_locker = TheLocker, + the_deleter = TheDeleter, the_registrar = TheRegistrar, + trace = Trace, global_lock_down = false}; +state(Else) -> + Else. + +%%% Trace tuples look like {Node, Now, Message, Nodes, Extra}. +%%% Nodes is the list as returned by nodes(). +%%% Extra is [] most of the time. +%%% +%%% init +%%% {nodedown,DownNode} +%%% {extra_nodedown,DownNode} +%%% {nodeup, UpNode} +%%% {added,AddedNodes}, Extra = [{new_nodes, NewNodes}, +%%% {abcast, Known}, +%%% {ops,Ops}] +%%% NewKnown = Known ++ AddedNodes +%%% AddedNodes = NewNodes -- Known +%%% NewNodes �r h�r den man f�rhandlat med plus de noder den k�nner till. +%%% {added, AddedNodes}, Extra = [{ops,Ops}] +%%% NewKnown = Known ++ AddedNodes +%%% Den (passiva) noden f�r Nodes som �r NewNodes +%%% hos den f�rhandlande. Sedan: AddedNodes = (Nodes -- Known) -- [node()]. +%%% Det �r som hos f�rhandlaren. +%%% {nodes_changed, {New,Old}} +%%% Every now and then the list [node() | nodes()] is checked for updates. +%%% New are the nodes that global does not know of (yet). +%%% {new_node_name, NewNode} +%%% Ignored. Someone changes the nodename dynamically. +%%% {ins_name, Node}, Extra = [Name, Pid] +%%% Node = node(Pid) +%%% {ins_name_ext, Node}, Extra = [Name, Pid] +%%% Node = node(Pid) +%%% {del_name, Node}, Extra = [Name, Pid] +%%% Node = node(Pid) +%%% {ins_lock, Node}, Extra = [Id, Pid] +%%% Node = node(Pid) +%%% {rem_lock, Node}, Extra = [Id, Pid] +%%% Node = node(Pid) +%%% {locker_succeeded, node()}, Extra = {First, Known} +%%% {locker_failed, node()}, Extra = {Tried, SoFar} +%%% The nodes in SoFar have been locked, could not lock Tried. +%%% +%%% Also trace of the creation and deletion of resolvers +%%% (this kind of resolvers are created when nodeup arrives from +%%% unknown nodes (there are also name resolvers...)). +%%% {new_resolver, Node}, Extra = [Tag, ResolverPid] +%%% {kill_resolver, Node}, Extra = [Tag, ResolverPid] +%%% {exit_resolver, Node}, Extra = [Tag] + +-record(node, { + node, + known = [], % #state.known (derived) + nodes = [], % nodes() + locks = [], % [{Id, [Pid, node(Pid)]}] (derived) + names = [], % [{Name, Pid, node(Pid)}] (derived) + resolvers = [], % [{Node, Tag, ResolverPid}] + n_locks = {0, % OK + 0, % Tried to lock the boss + 0, % Tried to lock other boss + 0}, % Tried to lock known + rejected = 0 % Lock OK, but later rejected + }). + +-record(w, {nodes = [], % [#node{}] + n = []}). + +t(File) -> + t(File, []). + +%%% What to search for in the output of t/2? +%%% - 'NEGOTIATIONS': this is a list of the name negotiations +%%% (the big picture); +%%% - '###' signals a possibly strange event; +%%% - 'spurious' is used for "tagging" such events; +%%% - 'resol ' could mean that some resolver process has not been removed; +%%% ... + +%% Options: +%% {show_state, From, To} +%% From = To = integer() | {integer(), integer()} +%% Examples: {7, 8} (show states between seconds 7.0 and 8.0); +%% {{1,431234},{2,432}} (between 1.431234 and 2.000432) +%% The state of a node includes locks, names, nodes, known, ... +%% Default is {{0,0}, {0,0}}, that is, do not show state. +%% show_state +%% same as {show_state, 0, 1 bsl 28}, that is, show every state +%% {show_trace, bool() +%% Show the complete trace as one list and per node pair. +%% Default is true. +t(File, Options) -> + {StateFun, ShowTrace} = + case options(Options, [show_state, show_trace]) of + [{From,To}, ST] -> + {fun(T, S) -> + Time = element(2, T), + if + Time >= From, Time =< To -> + io:format("===> ~p~n", [T]), + display_nodes("After", Time, S#w.nodes, T); + true -> + ok + end + end, ST}; + _ -> + erlang:error(badarg, [File, Options]) + end, + D1 = try + %% All nodes' trace is put on the file as one binary. + %% This could (and should?) be improved upon. + {ok, Bin} = file:read_file(File), + io:format("Size of trace file is ~p bytes~n", [size(Bin)]), + binary_to_term(Bin) + catch _:_ -> + {ok, [D0]} = file:consult(File), + D0 + end, + {D2, End} = case D1 of + {high_level_trace, ET, D3} -> + {D3, ET}; + _ -> + {D1, now()} + end, + D = adjust_nodes(D2), + {NodeNodeTrace, _NodeTrace, Trace, Base} = get_trace(D, End), + messages(D, Base, End), + + %io:format("NET~n ~p~n", [net_kernel_nodes(NodeTrace)]), + + io:format("NEGOTIATIONS:~n ~p~n", [negotiations(Trace)]), + + io:format("*** Complete trace ***~n"), + if + ShowTrace -> + show_trace(Trace), + io:format("--- End of complete trace ---~n"), + lists:map(fun({{Node,ActionNode},Ts}) -> + io:format("*** Trace for ~p on node ~p ***~n", + [ActionNode, Node]), + show_trace(lists:keysort(2, Ts)), + io:format("--- End of trace for ~p on node ~p ---~n", + [ActionNode, Node]) + end, NodeNodeTrace); + true -> ok + end, + io:format("*** Evaluation ***~n"), + {Fini, Spurious} = eval(Trace, StateFun), + io:format("*** End of evaluation ***~n"), + show_spurious(NodeNodeTrace, Spurious), + display_nodes("FINI", '', Fini), + ok. + +% show_trace(Trace) -> +% lists:foreach(fun({Node, {S,Mu}, Message, Nodes, Extra}) -> +% io:format("~2w.~6..0w ~w~n", [S, Mu, Node]), +% io:format(" ~p~n", [Message]), +% io:format(" Nodes: ~p~n", [Nodes]), +% case Extra of +% [] -> ok; +% _ -> io:format(" Extra: ~p~n", [Extra]) +% end +% end, Trace); +show_trace(Trace) -> + lists:map(fun(T) -> io:format("~p~n", [T]) end, Trace). + +get_trace(D, EndTime0) -> + NodeTrace0 = [{Node,lists:keysort(2, (state(State))#state.trace)} || + {Node,{info,State}} <- D, + case state(State) of + #state{trace = no_trace} -> + io:format("No trace for ~p~n", [Node]), + false; + #state{} -> + true; + Else -> + io:format("Bad state for ~p: ~p~n", + [Node, Else]), + false + end], + Trace0 = lists:keysort(2, lists:append([T || {_Node, T} <- NodeTrace0])), + Trace1 = sort_nodes(Trace0), + {Base, Trace2} = adjust_times(Trace1), + EndTime = adjust_time(EndTime0, Base), + io:format("The trace was generated at ~p~n", [EndTime]), + Trace = [T || T <- Trace2, element(2, T) < EndTime], + NodeTrace = [{Node, adjust_times(Ts, Base)} || + {Node, Ts} <- NodeTrace0], + NodeNodeTrace = + [{{Node,ActionNode}, T} || {Node, Ts} <- NodeTrace, + T <- Ts, + ActionNode <- action_nodes(T)], + {family(NodeNodeTrace), NodeTrace, Trace, Base}. + +adjust_nodes([E | Es]) -> + [adjust_nodes(E) | adjust_nodes(Es)]; +adjust_nodes(T) when is_tuple(T) -> + list_to_tuple(adjust_nodes(tuple_to_list(T))); +adjust_nodes(A) when is_atom(A) -> + adjust_node(A); +adjust_nodes(E) -> + E. + +sort_nodes(Ts) -> + [setelement(4, T, lists:sort(element(4, T))) || T <- Ts]. + +adjust_times([]) -> + {0, []}; +adjust_times([T1 | _]=Ts) -> + Base = element(2, T1), + {Base, adjust_times(Ts, Base)}. + +adjust_times(Ts, Base) -> + [setelement(2, adj_tag(T, Base), adjust_time(element(2, T), Base)) || + T <- Ts]. + +adj_tag({Node, Time, {M, Node2}, Nodes, Extra}=T, Base) -> + if + M =:= new_resolver; + M =:= kill_resolver; + M =:= exit_resolver -> + {Node, Time, {M, Node2}, Nodes, + [adjust_time(hd(Extra), Base) | tl(Extra)]}; + true -> + T + end. + +adjust_time(Time, Base) -> + musec2sec(timer:now_diff(Time, Base)). + +action_nodes({_Node, _Time, {_, Nodes}, _, _}) when is_list(Nodes) -> + Nodes; +action_nodes({_Node, _Time, {_, Node}, _, _}) -> + [Node]. + +%% Some of the names in global_SUITE.erl are recognized. +adjust_node(Node) -> + case atom_to_list(Node) of + "cp" ++ L -> + list_to_atom([$c, $p | lists:takewhile(fun is_digit/1, L)]); + "test_server" ++ _ -> + test_server; + "a_2" ++ _ -> + a_2; + "n_1" ++ _ -> + n_1; + "n_2" ++ _ -> + n_2; + "z_2" ++ _ -> + z_2; + "z_" ++ _ -> + z; + "b_" ++ _ -> + b; + "c_external_nodes" ++ _ -> + c_external_nodes; + _ -> + Node + end. + +is_digit(C) -> + (C >= $0) and (C =< $9). + +eval(Trace, Fun) -> + eval(Trace, {0, 0}, #w{}, Fun). + +eval([T | Ts], Time0, S0, Fun) -> + Time1 = element(2, T), + case is_fresh(S0#w.nodes) of + true -> + io:format("~p ***************** FRESH *****************~n", + [Time1]); + false -> + ok + end, + case time_diff(Time1, Time0) > 0 of + true -> + display_nodes("PAUS", Time1, S0#w.nodes, T); + false -> + ok + end, + S = eval_trace(T, S0), + Fun(T, S), + eval(Ts, Time1, S, Fun); +eval([], _, S, _Fun) -> + {S#w.nodes, lists:usort(S#w.n)}. + +%% Old. +eval_trace({Node, Time, {added,Added}, _Nodes, [_NewNodes,_Abc]}, S0) -> + added(Node, Added, Time, S0); +eval_trace({Node, Time, {added,Added}, _Nodes, []}, S0) -> + added(Node, Added, Time, S0); + + +eval_trace({Node, Time, {init, Node}, Nodes, []}, S0) -> + init(Node, Nodes, Time, S0); +eval_trace({Node, Time, {nodedown, DownNode}, Nodes, []}, S0) -> + node_down(Node, DownNode, Nodes, Time, S0); +eval_trace({Node, Time, {extra_nodedown, DownNode}, Nodes, []}, S0) -> + node_down(Node, DownNode, Nodes, Time, S0); +eval_trace({Node, Time, {nodeup, UpNode}, Nodes, []}, S0) -> + node_up(Node, UpNode, Nodes, Time, S0); +eval_trace({Node, Time, {added,Added}, _Nodes, [_NewNodes,_Abc,_Ops]}, S0) -> + added(Node, Added, Time, S0); +eval_trace({Node, Time, {added,Added}, _Nodes, [_Ops]}, S0) -> + added(Node, Added, Time, S0); +eval_trace({Node, Time, {nodes_changed, {New,Old}}, _Nodes, []}, S0) -> + nodes_changed(Node, New, Old, Time, S0); +eval_trace({Node, Time, {ins_name, PNode}, _Nodes, [Name, Pid]}, S0) -> + insert_name(Node, PNode, Time, Name, Pid, S0); +eval_trace({Node, Time, {del_name, PNode}, _Nodes, [Name, Pid]}, S0) -> + delete_name(Node, PNode, Time, Name, Pid, S0); +eval_trace({Node, Time, {ins_name_ext, PNode}, _Nodes, [Name, Pid]}, S0) -> + insert_external_name(Node, PNode, Time, Name, Pid, S0); +eval_trace({Node, Time, {ins_lock, PNode}, _Nodes, [Id, Pid]}, S0) -> + insert_lock(Node, PNode, Time, Id, Pid, S0); +eval_trace({Node, Time, {rem_lock, PNode}, _Nodes, [Id, Pid]}, S0) -> + remove_lock(Node, PNode, Time, Id, Pid, S0); +eval_trace({Node, Time, {locker_succeeded, _}, _Nodes,{_First,_Known}}, S0) -> + locker_succeeded(Node, Time, S0); +eval_trace({Node, Time, {lock_rejected, _}, _Nodes, Known}, S0) -> + lock_rejected(Node, Time, Known, S0); +eval_trace({Node, Time, {locker_failed, _}, _Nodes, {Tried,SoFar}}, S0) -> + locker_failed(Node, Time, Tried, SoFar, S0); +eval_trace({Node, Time, {new_resolver, RNode}, _Nodes, [Tag, ResPid]}, S0) -> + new_resolver(Node, Time, RNode, Tag, ResPid, S0); +eval_trace({Node, Time, {kill_resolver, RNode}, _Nodes, [Tag,_ResPid]}, S0) -> + stop_resolver(Node, Time, RNode, Tag, kill, S0); +eval_trace({Node, Time, {exit_resolver, RNode}, _Nodes, [Tag]}, S0) -> + stop_resolver(Node, Time, RNode, Tag, exit, S0); +eval_trace(_Ignored, S) -> +io:format("ignored ~p~n", [_Ignored]), + S. + +init(_Node, [], _Time, S) -> + S; +init(Node, NodesList, Time, S) -> + io:format("### ~p ~p: already in nodes(): ~p~n", [Node, Time, NodesList]), + S. + +node_down(Node, DownNode, NodesList, Time, S0) -> + case get_node(Node, S0) of + {ok, #node{known = Known, nodes = Nodes}=N} -> + case lists:member(DownNode, Nodes) of + true -> + S1 = case lists:member(DownNode, Known) of + true -> + S0; + false -> + io:format("### ~p ~p:~n " + "nodedown but unknown ~p~n", + [Node, Time, DownNode]), + case lists:member(DownNode, Nodes) of + true -> + io:format("(but note that ~p" + " is member of nodes())~n", + [DownNode]); + false -> + ok + end, + add_spurious(Node, DownNode, S0, Time) + end, + NewKnown = lists:delete(DownNode, Known), + NewNodes = lists:delete(DownNode, Nodes), + put_node(N#node{known = NewKnown, nodes = NewNodes}, S1); + false -> + io:format("### ~p ~p:~n spurious nodedown from ~p~n " + "~p~n", [Node, Time, DownNode, NodesList]), + NewKnown = lists:delete(DownNode, Known), + S1 = put_node(N#node{known = NewKnown,nodes = Nodes}, S0), + add_spurious(Node, DownNode, S1, Time) + end; + not_ok -> + io:format("### ~p ~p:~n unknown node got nodedown from ~p~n", + [Node, Time, DownNode]), + add_spurious(Node, DownNode, S0, Time) + end. + +node_up(Node, UpNode, NodesList, Time, S) -> + case get_node(Node, S) of + {ok, #node{nodes = Nodes}=N} -> + case lists:member(UpNode, Nodes) of + true -> + io:format("### ~p ~p:~n spurious nodeup from ~p~n " + "~p~n", [Node, Time, UpNode, NodesList]), + add_spurious(Node, UpNode, S, Time); + false -> + put_node(N#node{nodes = lists:sort([UpNode | Nodes])}, S) + end; + not_ok -> + S#w{nodes = [#node{node = Node, nodes = [UpNode]} | S#w.nodes]} + end. + +added(Node, Added, Time, S0) -> + case get_node(Node, S0) of + {ok, #node{known = Known, nodes = Nodes}=N} -> + case Known -- (Known -- Added) of + [] -> + S1 = put_node(N#node{known = lists:sort(Added ++ Known), + nodes = Nodes}, S0), + case lists:member(Node, Added) of + true -> + io:format("### ~p ~p:~n adding node()" + " to known (~p)~n", [Node, Time,Added]), + add_spurious(Node, Added, S1, Time); + false -> + S1 + end; + AK -> + io:format("### ~p ~p:~n added already known ~p~n", + [Node, Time, AK]), + S1 = put_node(N#node{known = lists:usort(Added ++ Known), + nodes = Nodes}, S0), + add_spurious(Node, AK, S1, Time) + end; + not_ok -> + io:format("### ~p ~p:~n unknown node got added ~p~n", + [Node, Time, Added]), + S1 = S0#w{nodes = [#node{node = Node, known = Added} | + S0#w.nodes]}, + add_spurious(Node, Added, S1, Time) + end. + +nodes_changed(Node, New, Old, Time, S) -> + io:format("### ~p ~p:~n nodes changed, new are ~p, old are ~p~n", + [Node, Time, New, Old]), + S. + +insert_external_name(Node, PNode, Time, Name, Pid, S) -> + insert_name(Node, PNode, Time, Name, Pid, S). + +insert_name(Node, PNode, Time, Name, Pid, S0) -> + RegName = {Name, Pid, PNode}, + case get_node(Node, S0) of + {ok, #node{names = Names}=N} -> + case lists:keysearch(Name, 1, Names) of + {value, {Name, OldPid, OldPNode}} -> + io:format("### ~p ~p:~n name ~p already registered " + "for ~p on ~p~n", + [Node, Time, Name, OldPid, OldPNode]), + add_spurious(Node, [PNode], S0, Time); + false -> + case lists:keysearch(Pid, 2, Names) of + {value, {OldName, Pid, OldPNode}} -> + io:format("### ~p ~p:~n pid ~p already " + "registered as ~p on ~p~n", + [Node, Time, Pid, OldName, OldPNode]), + add_spurious(Node, [PNode], S0, Time); + false -> + put_node(N#node{names = [RegName | Names]}, S0) + end + end; + not_ok -> + io:format("### ~p ~p:~n unknown node registered ~p for ~p " + "on ~p~n", [Node, Time, Name, Pid, PNode]), + Known = add_to_known(Node, PNode, []), + N = #node{node = Node, known = Known, names = [RegName]}, + S1 = S0#w{nodes = [N | S0#w.nodes]}, + add_spurious(Node, [PNode], S1, Time) + end. + +delete_name(Node, PNode, Time, Name, Pid, S0) -> + case get_node(Node, S0) of + {ok, #node{names = Names}=N} -> + case lists:keysearch(Name, 1, Names) of + {value, {Name, Pid, PNode}} -> + NewNames = lists:keydelete(Name, 1, Names), + put_node(N#node{names = NewNames}, S0); + {value, {Name, Pid2, PNode2}} -> % bad log + io:format("### ~p ~p:~n name ~p not registered " + "for ~p on ~p but for ~p on ~p~n", + [Node, Time, Name, Pid, PNode, Pid2, PNode2]), + add_spurious(Node, [PNode], S0, Time); + false -> + io:format("### ~p ~p:~n name ~p not registered " + "for ~p on ~p~n", + [Node, Time, Name, Pid, PNode]), + add_spurious(Node, [PNode], S0, Time) + end; + not_ok -> + io:format("### ~p ~p:~n unknown node deleted ~p for ~p on ~p~n", + [Node, Time, Name, Pid, PNode]), + Known = add_to_known(Node, PNode, []), + N = #node{node = Node, known = Known}, + S1 = S0#w{nodes = [N | S0#w.nodes]}, + add_spurious(Node, [PNode], S1, Time) + end. + +insert_lock(Node, PNode, Time, Id, Pid, S0) -> + Lock = {Pid, PNode}, + case get_node(Node, S0) of + {ok, #node{locks = NLocks}=N} -> + case lists:keysearch(Id, 1, NLocks) of + {value, {Id, OldLocks}} -> + case lists:member(Lock, OldLocks) of + true -> + io:format("### ~p ~p:~n lock ~p already set " + "for ~p on ~p~n", + [Node, Time, Id, Pid, PNode]), + %% This is not so strange, actually. + add_spurious(Node, [PNode], S0, Time); + false -> + NewLocks = {Id, [Lock | OldLocks]}, + Ls = lists:keyreplace(Id, 1, NLocks, NewLocks), + put_node(N#node{locks = Ls}, S0) + end; + false -> + put_node(N#node{locks = [{Id,[Lock]}|N#node.locks]}, S0) + end; + not_ok -> + Known = add_to_known(Node, PNode, []), + N = #node{node = Node, known = Known, locks = [{Id, [Lock]}]}, + S1 = S0#w{nodes = [N | S0#w.nodes]}, + if + Node =/= PNode -> + io:format("### ~p ~p:~n unknown pid ~p locked ~p on " + "~p~n", [Node, Time, Pid, Id, PNode]), + add_spurious(Node, [PNode], S1, Time); + true -> + S1 + end + end. + +remove_lock(Node, PNode, Time, Id, Pid, S0) -> + Lock = {Pid, PNode}, + case get_node(Node, S0) of + {ok, #node{locks = NLocks}=N} -> + case lists:keysearch(Id, 1, NLocks) of + {value, {Id, OldLocks}} -> + case lists:member(Lock, OldLocks) of + true -> + NewLocks = lists:delete(Lock, OldLocks), + Ls = case NewLocks of + [] -> + lists:keydelete(Id, 1, NLocks); + _ -> + lists:keyreplace(Id, 1, NLocks, + {Id, NewLocks}) + end, + put_node(N#node{locks = Ls}, S0); + false -> + io:format("### ~p ~p:~n lock ~p not set " + "by ~p on ~p~n", + [Node, Time, Id, Pid, PNode]), + add_spurious(Node, [PNode], S0, Time) + end; + false -> + io:format("### ~p ~p:~n lock ~p not set " + "by ~p on ~p~n", + [Node, Time, Id, Pid, PNode]), + add_spurious(Node, [PNode], S0, Time) + end; + not_ok -> + io:format("### ~p ~p:~n ~p unlocked ~p on unknown node ~p~n", + [Node, Time, Pid, Id, PNode]), + Known = add_to_known(Node, PNode, []), + N = #node{node = Node, known = Known}, + S1 = S0#w{nodes = [N | S0#w.nodes]}, + add_spurious(Node, [PNode], S1, Time) + end. + +%% This is just statistics... +locker_succeeded(Node, Time, S0) -> + case get_node(Node, S0) of + {ok, #node{n_locks = {Ok,Boss,NodeX,Bad}}=N} -> + put_node(N#node{n_locks = {Ok+1,Boss,NodeX,Bad}}, S0); + not_ok -> + io:format("### ~p ~p:~n unknown node's locker succeeded~n", + [Node, Time]), + add_spurious(Node, [Node], S0, Time) + end. + +lock_rejected(Node, Time, _Known, S0) -> + case get_node(Node, S0) of + {ok, #node{rejected = Rej}=N} -> + put_node(N#node{rejected = Rej+1}, S0); + not_ok -> + io:format("### ~p ~p:~n unknown node's lock rejected~n", + [Node, Time]), + add_spurious(Node, [Node], S0, Time) + end. + +locker_failed(Node, Time, Tried, SoFar, S0) -> + case get_node(Node, S0) of + {ok, #node{known = Known, n_locks = {Ok,Boss,NodeX,Bad}}=N} -> + TheBoss = lists:max([Node | Known]), + Cheap = (Tried =:= [TheBoss]), + RatherCheap = ((SoFar -- [Node, TheBoss]) =:= []) and + ((Tried -- [Node, TheBoss]) =/= []), + if + Cheap -> + put_node(N#node{n_locks = {Ok,Boss+1,NodeX,Bad}}, S0); + RatherCheap -> + put_node(N#node{n_locks = {Ok,Boss,NodeX+1,Bad}}, S0); + true -> + put_node(N#node{n_locks = {Ok,Boss,NodeX,Bad+1}}, S0) + end; + not_ok -> + io:format("### ~p ~p:~n unknown node's locker failed~n", + [Node, Time]), + add_spurious(Node, [Node], S0, Time) + end. + +new_resolver(Node, Time, ResNode, Tag, ResPid, S0) -> + case get_node(Node, S0) of + {ok, #node{resolvers = Rs}=N} -> + put_node(N#node{resolvers = [{ResNode, Tag, ResPid} | Rs]}, S0); + not_ok -> + io:format("### ~p ~p:~n resolver created for unknown node~n", + [Node, Time]), + add_spurious(Node, [Node], S0, Time) + end. + +stop_resolver(Node, Time, ResNode, Tag, How, S0) -> + case get_node(Node, S0) of + {ok, #node{resolvers = Rs}=N} -> + case lists:keysearch(Tag, 2, Rs) of + {value, {ResNode, Tag, _ResPid}} -> + NewRs = lists:keydelete(Tag, 2, Rs), + put_node(N#node{resolvers = NewRs}, S0); + false -> + case lists:keysearch(ResNode, 1, Rs) of + {value, {ResNode, _Tag2, _ResPid2}} -> + NewRs = lists:keydelete(ResNode, 1, Rs), + put_node(N#node{resolvers = NewRs}, S0); + false when How =:= exit -> + io:format("### ~p ~p:~n there is no resolver " + "with tag ~p on node ~p~n", + [Node, Time, Tag, ResNode]), + add_spurious(Node, [ResNode], S0, Time); + false when How =:= kill -> + S0 + end + end; + not_ok -> + io:format("### ~p ~p:~n resolver stopped for unknown node~n", + [Node, Time]), + add_spurious(Node, [Node], S0, Time) + end. + +add_to_known(Node, NodeToAdd, Known) -> + if + Node =:= NodeToAdd -> + Known; + true -> + lists:sort([NodeToAdd | Known]) + end. + +get_node(Node, S) -> + case lists:keysearch(Node, #node.node, S#w.nodes) of + {value, N} -> + {ok, N}; + false -> + not_ok + end. + +put_node(#node{node = Node, known = [], nodes = [], locks = [], names = [], + n_locks = {0,0,0,0}}, + S) -> + S#w{nodes = lists:keydelete(Node, #node.node, S#w.nodes)}; +put_node(N, S) -> + S#w{nodes = lists:keyreplace(N#node.node, #node.node, S#w.nodes, N)}. + +is_fresh(#node{known = [], nodes = [], locks = [], names = []}) -> + true; +is_fresh(#node{}) -> + false; +is_fresh([]) -> + true; +is_fresh([N | Ns]) -> + is_fresh(N) andalso is_fresh(Ns). + +add_spurious(Node, ActionNodes, S, Time) when is_list(ActionNodes) -> + S#w{n = [{{Node,N},Time}|| N <- ActionNodes] ++ S#w.n}; +add_spurious(Node, ActionNode, S, Time) -> + add_spurious(Node, [ActionNode], S, Time). + +messages(D, Base, End) -> + messages1(no_info(D), no_info), + messages1(resolvers(D, Base, End), resolvers), + messages1(syncers(D), syncers). + +messages1(M, ST) -> + [foo || {Node, T} <- M, + ok =:= io:format(ms(ST), [Node, T])]. + +ms(no_info) -> + "~p: ~p~n"; +ms(resolvers) -> + "~p: resolvers ~p~n"; +ms(syncers) -> + "~p: syncers ~p~n". + +no_info(D) -> + [{Node,no_info} || {Node, no_info} <- D]. + +resolvers(D, Base, End) -> + [{Node, + [{N,adjust_time(T, Base),P} || {N, T, P} <- Rs, T < End]} || + {Node, {info,State}} <- D, + is_record(State, state), + [] =/= (Rs = (state(State))#state.resolvers)]. + +syncers(D) -> + [{Node,Ss} || {Node, {info,State}} <- D, + is_record(State, state), + [] =/= (Ss = (state(State))#state.syncers)]. + +net_kernel_nodes(NodeTrace) -> + [{Node, nkn(Trace, [])} || {Node, Trace} <- NodeTrace]. + +nkn([], _Nodes) -> + []; +nkn([{Node, Time, _Message, Ns, _X} | Ts], Nodes) -> + {NewS, _, OldS} = sofs:symmetric_partition(sofs:set(Ns), sofs:set(Nodes)), + New = sofs:to_external(NewS), + Old = sofs:to_external(OldS), + [{Node, Time, {newnode, N}, []} || N <- New] ++ + [{Node, Time, {oldnode, N}, []} || N <- Old] ++ + nkn(Ts, (Nodes -- Old) ++ New). + +negotiations(Trace) -> + Ns = [{Node,T,Added,X} || + {Node,T,{added,Added},_Nodes,X} <- Trace], + Pass = [{passive,Node,T,Added} || + {Node,T,Added,[_Ops]} <- Ns], + Act = [{active,Node,T,Other,Added,NewNodes} || + {Node,T,Added,[{new_nodes,[Other|_]=NewNodes},_Abcast,_Ops]} <- Ns], + Act ++ Pass. + +show_spurious(NodeTrace, Spurious) -> + Pairs = [{Node,ActionNode} || {{Node,ActionNode}, _Time} <- Spurious], + S = sofs:restriction(sofs:relation(NodeTrace), sofs:set(Pairs)), + [foo || + {{{Node,ANode},Times}, + {{Node,ANode},Ts}} <- lists:zip(family(Spurious), + sofs:to_external(S)), + show_spurious(Node, ANode, Times, lists:keysort(2, Ts))]. + +show_spurious(Node, ActionNode, Times, Ts) -> + io:format("** Actions for ~p on node ~p **~n", [ActionNode, Node]), + lists:map(fun(T) -> spurious(Node, T, Times) end, Ts), + io:format("-- End of actions for ~p on node ~p --~n", [ActionNode, Node]), + true. + +spurious(Node, Trace, Times) -> + As = case Trace of + {Node, _T0, {init, Node}, _Nodes, _} -> + init; % should not happen, I guess + {Node, _T0, {nodedown, _ActionNode}, _Nodes, _} -> + nodedown; + {Node, _T0, {extra_nodedown, _ActionNode}, _Nodes, _} -> + extra_nodedown; + {Node, _T0, {nodeup, _ActionNode}, _Nodes, _} -> + nodeup; + {Node, _T0, {added, Added}, _Nodes, [_Ops]} -> + {passive, Added}; + {Node, _T0, {added, Added}, _Nodes, [_NewNodes,_AbCast,_Ops]} -> + {negotiator, Added}; + {Node, _T0, {ins_lock, PNode}, _Nodes, [Id, Pid]} -> + {insert_lock, [Id, Pid, PNode]}; + {Node, _T0, {rem_lock, PNode}, _Nodes, [Id, Pid]} -> + {remove_lock, [Id, Pid, PNode]}; + {Node, _T0, {ins_name, PNode}, _Nodes, [Name, Pid]} -> + {insert_name, [Name, Pid, PNode]}; + {Node, _T0, {del_name, PNode}, _Nodes, [Name, Pid]} -> + {insert_name, [Name, Pid, PNode]}; + {Node, _T0, {nodes_changed, CNode}, _Nodes, []} -> + {nodes_changed, [CNode]}; + {Node, _T0, {Any, Some}, _Nodes, X} -> + {Any, [Some | X]} + end, + T = element(2, Trace), + _Nodes2 = element(4, Trace), + TS = ["(spurious)" || lists:member(T, Times)], + io:format("~p: ~p ~s~n", [T, As, TS]), +% io:format(" ~w~n", [_Nodes2]), + ok. + +display_nodes(Why, Time, Nodes) -> + display_nodes(Why, Time, Nodes, none). + +display_nodes(Why, Time, Nodes, LastTrace) -> + io:format("~p **** ~s ****~n", [Time, Why]), + {OkL, BossL, NodeXL, BadL} = unzip4([L || #node{n_locks = L} <- Nodes]), + [NOk, NBoss, NNodeX, NBad] = + [lists:sum(L) || L <- [OkL, BossL, NodeXL, BadL]], + Rejected = lists:sum([Rej || #node{rejected = Rej} <- Nodes]), + io:format("Locks: (~w+~w+~w=~w)/~w, ~w of ~w rejected~n", + [NOk, NBoss, NNodeX, NOk+NBoss+NNodeX, NOk+NBoss+NNodeX+NBad, + Rejected, NOk]), + lists:foreach(fun(#node{node = Node, known = Known, nodes = Ns, + locks = Locks, names = Names, + n_locks = {Ok, Boss, NodeX, Bad}, + resolvers = Resolvers0, + rejected = Rej}) -> + NodeL = io_lib:format("~p: ",[Node]), + io:format("~sknown ~p~n", [NodeL, Known]), + Sp = spaces(NodeL), + case Ns =:= Known of + true -> ok; + false -> display_list(Sp, nodes, Ns) + end, + display_list(Sp, locks, Locks), + display_list(Sp, names, lists:sort(Names)), + Resolvers = lists:sort(Resolvers0), + _ResNs = [R || {R,_,_} <- Resolvers], + %% Should check trace on this node (Node) only: + New = [N || {_,_,{nodeup,N},_,_} <- [LastTrace]], + _ResAllowed = (Ns -- New) -- Known, +%% Displays too much junk. +% case ResAllowed =:= ResNs of +% true -> ok; +% false -> display_list(Sp, resol, Resolvers) +% end, + %% This is less bulky: + case Known =:= Ns of + true -> display_list(Sp, resol, Resolvers); + false -> ok + end, + case {Ok, Boss, NodeX, Bad} of + {0, 0, 0, 0} -> ok; + _ -> io:format("~slocks (~w+~w+~w=~w)/~w, " + "~w of ~w rejected~n", + [Sp, Ok, Boss, NodeX, + Ok+Boss+NodeX,Ok+Boss+NodeX+Bad, + Rej, Ok]) + end + end, lists:keysort(#node.node, Nodes)), + io:format("\n"). + +display_list(_S, _What, []) -> + ok; +display_list(S, What, L) -> + io:format("~s~p ~p~n", [S, What, L]). + +spaces(Iolist) -> + lists:duplicate(iolist_size(Iolist), $\s). + +family(R) -> + sofs:to_external(sofs:relation_to_family(sofs:relation(R))). + +time_diff({S1,MyS1}, {S0,MyS0}) -> + ((S1*1000000+MyS1) - (S0*1000000+MyS0)) div 1000000. + +musec2sec(T) -> + S = T div 1000000, + M = (T - S * 1000000), + {S, M}. + +%%% Options + +options(Options, Keys) when is_list(Options) -> + options(Options, Keys, []); +options(Option, Keys) -> + options([Option], Keys, []). + +options(Options0, [Key | Keys], L) when is_list(Options0) -> + Options = case lists:member(Key, Options0) of + true -> + [atom_option(Key) | lists:delete(Key, Options0)]; + false -> + Options0 + end, + V = case lists:keysearch(Key, 1, Options) of + {value, {show_state, From, To}} when is_integer(From), From >= 0, + is_integer(To), To >= From -> + {ok, {{From,0}, {To,0}}}; + {value, {show_state, {From, FromMusec}, + {To, ToMusec}}} when is_integer(From), + From >= 0, + is_integer(To), + To >= From, + FromMusec >= 0, + FromMusec =< 999999, + ToMusec >= 0, + ToMusec =< 999999 -> + {ok, {{From,FromMusec}, {To,ToMusec}}}; + {value, {show_state, false}} -> + {value, default_option(show_state)}; + {value, {show_trace, Bool}} when Bool; not Bool -> + {ok, Bool}; + {value, {Key, _}} -> + badarg; + false -> + Default = default_option(Key), + {ok, Default} + end, + case V of + badarg -> + badarg; + {ok, Value} -> + NewOptions = lists:keydelete(Key, 1, Options), + options(NewOptions, Keys, [Value | L]) + end; +options([], [], L) -> + lists:reverse(L); +options(_Options, _, _L) -> + badarg. + +default_option(show_state) -> {{0,0}, {0,0}}; +default_option(show_trace) -> true. + +atom_option(show_state) -> + {show_state, 0, 1 bsl 28}; +atom_option(show_trace) -> + {show_trace, true}; +atom_option(_) -> + erlang:error(program_error, []). + +unzip4(Ts) -> unzip4(Ts, [], [], [], []). + +unzip4([{X, Y, Z, W} | Ts], Xs, Ys, Zs, Ws) -> + unzip4(Ts, [X | Xs], [Y | Ys], [Z | Zs], [W | Ws]); +unzip4([], Xs, Ys, Zs, Ws) -> + {lists:reverse(Xs), lists:reverse(Ys), + lists:reverse(Zs), lists:reverse(Ws)}. + |