1%% 2%% %CopyrightBegin% 3%% 4%% Copyright Ericsson AB 2007-2016. All Rights Reserved. 5%% 6%% Licensed under the Apache License, Version 2.0 (the "License"); 7%% you may not use this file except in compliance with the License. 8%% You may obtain a copy of the License at 9%% 10%% http://www.apache.org/licenses/LICENSE-2.0 11%% 12%% Unless required by applicable law or agreed to in writing, software 13%% distributed under the License is distributed on an "AS IS" BASIS, 14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 15%% See the License for the specific language governing permissions and 16%% limitations under the License. 17%% 18%% %CopyrightEnd% 19%% 20-module(global_trace). 21 22%%% 23%%% Inspection of High Level Trace created by global.erl. 24%%% 25 26%%% A few handy functions when running the test_server 27%%% 28 29d() -> 30 lists:foreach(fun(F) -> dd(F, []) end, last()). 31 32d(Testcase) -> 33 d(Testcase, []). 34 35%% Skip "global_" from T. 36d(Testcase, Options) -> 37 [Filename] = tmp_files(Testcase), 38 dd(Filename, Options). 39 40dd(Filename, Options) -> 41 io:format("\n======= ~s \n", [Filename]), 42 t(Filename, Options). 43 44last() -> 45 tmp_files("*"). 46 47%% global_groups_change: one node is restarted 48%% global_mass_death: nodes are stopped 49%% global_lock_die: two spurious (trying to remove locks taken by other pid) 50%% global_otp_5640: 4 spurious (names registered again &c) 51tmp_files(A) when is_atom(A) -> 52 tmp_files(atom_to_list(A)); 53tmp_files(T) when is_list(T) -> 54 Logs = logdir(), 55 Dir = lists:last(filelib:wildcard(filename:join(Logs, "*"))), 56 filelib:wildcard(filename:join([Dir, log_private, "global_" ++ T])). 57 58%logdir() -> 59% "/net/yoshi/ldisk/daily_build/otp_norel_linux_r11b.2007-02-18_19/" 60% "test/test_server/global_SUITE.logs"; 61%logdir() -> 62% "/ldisk/daily_build/otp_norel_linux_suse_r11b.2007-02-07_19/test/" 63% "test_server/global_SUITE.logs"; 64logdir() -> 65 "/tmp/tests/test_server/global_SUITE.logs". 66 67 68 69%%% The contents of this file is by no means fixed; the printouts are 70%%% updated depending on the problems at hand. Not everything has been 71%%% designed very carefully :) 72%%% 73%%% For one thing, the trace from all nodes are written onto the file 74%%% as one single term. One term per node would be better. &c. 75 76-compile(export_all). 77 78-record(state, {connect_all, known = [], synced = [], 79 resolvers = [], syncers = [], node_name = node(), 80 the_locker, the_deleter, the_registrar, trace = [], 81 global_lock_down 82 }). 83 84%% Compatible with different versions. 85state(#state{}=S) -> 86 S; 87state({state, ConnectAll, Known, Synced, LockersResolvers, Syncers, 88 NodeName, TheLocker, TheDeleter}) -> 89 %% r10b: Lockers, r10b_patched, r11b: Resolvers 90 #state{connect_all = ConnectAll, known = Known, synced = Synced, 91 resolvers = LockersResolvers, syncers = Syncers, 92 node_name = NodeName, the_locker = TheLocker, 93 the_deleter = TheDeleter, the_registrar = undefined, trace = []}; 94state({state, ConnectAll, Known, Synced, Resolvers, Syncers, 95 NodeName, TheLocker, TheDeleter, Trace}) -> 96 %% r11b, some time before r11b-3 97 #state{connect_all = ConnectAll, known = Known, synced = Synced, 98 resolvers = Resolvers, syncers = Syncers, 99 node_name = NodeName, the_locker = TheLocker, 100 the_deleter = TheDeleter, the_registrar = undefined, 101 trace = Trace}; 102state({state, ConnectAll, Known, Synced, Resolvers, Syncers, 103 NodeName, TheLocker, TheDeleter, TheRegistrar, Trace}) -> 104 %% r11b, some time after r11b-3 105 #state{connect_all = ConnectAll, known = Known, synced = Synced, 106 resolvers = Resolvers, syncers = Syncers, 107 node_name = NodeName, the_locker = TheLocker, 108 the_deleter = TheDeleter, the_registrar = TheRegistrar, 109 trace = Trace, global_lock_down = false}; 110state(Else) -> 111 Else. 112 113%%% Trace tuples look like {Node, Now, Message, Nodes, Extra}. 114%%% Nodes is the list as returned by nodes(). 115%%% Extra is [] most of the time. 116%%% 117%%% init 118%%% {nodedown,DownNode} 119%%% {extra_nodedown,DownNode} 120%%% {nodeup, UpNode} 121%%% {added,AddedNodes}, Extra = [{new_nodes, NewNodes}, 122%%% {abcast, Known}, 123%%% {ops,Ops}] 124%%% NewKnown = Known ++ AddedNodes 125%%% AddedNodes = NewNodes -- Known 126%%% NewNodes är här den man förhandlat med plus de noder den känner till. 127%%% {added, AddedNodes}, Extra = [{ops,Ops}] 128%%% NewKnown = Known ++ AddedNodes 129%%% Den (passiva) noden får Nodes som är NewNodes 130%%% hos den förhandlande. Sedan: AddedNodes = (Nodes -- Known) -- [node()]. 131%%% Det är som hos förhandlaren. 132%%% {nodes_changed, {New,Old}} 133%%% Every now and then the list [node() | nodes()] is checked for updates. 134%%% New are the nodes that global does not know of (yet). 135%%% {new_node_name, NewNode} 136%%% Ignored. Someone changes the nodename dynamically. 137%%% {ins_name, Node}, Extra = [Name, Pid] 138%%% Node = node(Pid) 139%%% {ins_name_ext, Node}, Extra = [Name, Pid] 140%%% Node = node(Pid) 141%%% {del_name, Node}, Extra = [Name, Pid] 142%%% Node = node(Pid) 143%%% {ins_lock, Node}, Extra = [Id, Pid] 144%%% Node = node(Pid) 145%%% {rem_lock, Node}, Extra = [Id, Pid] 146%%% Node = node(Pid) 147%%% {locker_succeeded, node()}, Extra = {First, Known} 148%%% {locker_failed, node()}, Extra = {Tried, SoFar} 149%%% The nodes in SoFar have been locked, could not lock Tried. 150%%% 151%%% Also trace of the creation and deletion of resolvers 152%%% (this kind of resolvers are created when nodeup arrives from 153%%% unknown nodes (there are also name resolvers...)). 154%%% {new_resolver, Node}, Extra = [Tag, ResolverPid] 155%%% {kill_resolver, Node}, Extra = [Tag, ResolverPid] 156%%% {exit_resolver, Node}, Extra = [Tag] 157 158-record(node, { 159 node, 160 known = [], % #state.known (derived) 161 nodes = [], % nodes() 162 locks = [], % [{Id, [Pid, node(Pid)]}] (derived) 163 names = [], % [{Name, Pid, node(Pid)}] (derived) 164 resolvers = [], % [{Node, Tag, ResolverPid}] 165 n_locks = {0, % OK 166 0, % Tried to lock the boss 167 0, % Tried to lock other boss 168 0}, % Tried to lock known 169 rejected = 0 % Lock OK, but later rejected 170 }). 171 172-record(w, {nodes = [], % [#node{}] 173 n = []}). 174 175t(File) -> 176 t(File, []). 177 178%%% What to search for in the output of t/2? 179%%% - 'NEGOTIATIONS': this is a list of the name negotiations 180%%% (the big picture); 181%%% - '###' signals a possibly strange event; 182%%% - 'spurious' is used for "tagging" such events; 183%%% - 'resol ' could mean that some resolver process has not been removed; 184%%% ... 185 186%% Options: 187%% {show_state, From, To} 188%% From = To = integer() | {integer(), integer()} 189%% Examples: {7, 8} (show states between seconds 7.0 and 8.0); 190%% {{1,431234},{2,432}} (between 1.431234 and 2.000432) 191%% The state of a node includes locks, names, nodes, known, ... 192%% Default is {{0,0}, {0,0}}, that is, do not show state. 193%% show_state 194%% same as {show_state, 0, 1 bsl 28}, that is, show every state 195%% {show_trace, bool() 196%% Show the complete trace as one list and per node pair. 197%% Default is true. 198t(File, Options) -> 199 {StateFun, ShowTrace} = 200 case options(Options, [show_state, show_trace]) of 201 [{From,To}, ST] -> 202 {fun(T, S) -> 203 Time = element(2, T), 204 if 205 Time >= From, Time =< To -> 206 io:format("===> ~p~n", [T]), 207 display_nodes("After", Time, S#w.nodes, T); 208 true -> 209 ok 210 end 211 end, ST}; 212 _ -> 213 erlang:error(badarg, [File, Options]) 214 end, 215 D1 = try 216 %% All nodes' trace is put on the file as one binary. 217 %% This could (and should?) be improved upon. 218 {ok, Bin} = file:read_file(File), 219 io:format("Size of trace file is ~p bytes~n", [size(Bin)]), 220 binary_to_term(Bin) 221 catch _:_ -> 222 {ok, [D0]} = file:consult(File), 223 D0 224 end, 225 {D2, End} = case D1 of 226 {high_level_trace, ET, D3} -> 227 {D3, ET}; 228 _ -> 229 {D1, now()} 230 end, 231 D = adjust_nodes(D2), 232 {NodeNodeTrace, _NodeTrace, Trace, Base} = get_trace(D, End), 233 messages(D, Base, End), 234 235 %io:format("NET~n ~p~n", [net_kernel_nodes(NodeTrace)]), 236 237 io:format("NEGOTIATIONS:~n ~p~n", [negotiations(Trace)]), 238 239 io:format("*** Complete trace ***~n"), 240 if 241 ShowTrace -> 242 show_trace(Trace), 243 io:format("--- End of complete trace ---~n"), 244 lists:map(fun({{Node,ActionNode},Ts}) -> 245 io:format("*** Trace for ~p on node ~p ***~n", 246 [ActionNode, Node]), 247 show_trace(lists:keysort(2, Ts)), 248 io:format("--- End of trace for ~p on node ~p ---~n", 249 [ActionNode, Node]) 250 end, NodeNodeTrace); 251 true -> ok 252 end, 253 io:format("*** Evaluation ***~n"), 254 {Fini, Spurious} = eval(Trace, StateFun), 255 io:format("*** End of evaluation ***~n"), 256 show_spurious(NodeNodeTrace, Spurious), 257 display_nodes("FINI", '', Fini), 258 ok. 259 260% show_trace(Trace) -> 261% lists:foreach(fun({Node, {S,Mu}, Message, Nodes, Extra}) -> 262% io:format("~2w.~6..0w ~w~n", [S, Mu, Node]), 263% io:format(" ~p~n", [Message]), 264% io:format(" Nodes: ~p~n", [Nodes]), 265% case Extra of 266% [] -> ok; 267% _ -> io:format(" Extra: ~p~n", [Extra]) 268% end 269% end, Trace); 270show_trace(Trace) -> 271 lists:map(fun(T) -> io:format("~p~n", [T]) end, Trace). 272 273get_trace(D, EndTime0) -> 274 NodeTrace0 = [{Node,lists:keysort(2, (state(State))#state.trace)} || 275 {Node,{info,State}} <- D, 276 case state(State) of 277 #state{trace = no_trace} -> 278 io:format("No trace for ~p~n", [Node]), 279 false; 280 #state{} -> 281 true; 282 Else -> 283 io:format("Bad state for ~p: ~p~n", 284 [Node, Else]), 285 false 286 end], 287 Trace0 = lists:keysort(2, lists:append([T || {_Node, T} <- NodeTrace0])), 288 Trace1 = sort_nodes(Trace0), 289 {Base, Trace2} = adjust_times(Trace1), 290 EndTime = adjust_time(EndTime0, Base), 291 io:format("The trace was generated at ~p~n", [EndTime]), 292 Trace = [T || T <- Trace2, element(2, T) < EndTime], 293 NodeTrace = [{Node, adjust_times(Ts, Base)} || 294 {Node, Ts} <- NodeTrace0], 295 NodeNodeTrace = 296 [{{Node,ActionNode}, T} || {Node, Ts} <- NodeTrace, 297 T <- Ts, 298 ActionNode <- action_nodes(T)], 299 {family(NodeNodeTrace), NodeTrace, Trace, Base}. 300 301adjust_nodes([E | Es]) -> 302 [adjust_nodes(E) | adjust_nodes(Es)]; 303adjust_nodes(T) when is_tuple(T) -> 304 list_to_tuple(adjust_nodes(tuple_to_list(T))); 305adjust_nodes(A) when is_atom(A) -> 306 adjust_node(A); 307adjust_nodes(E) -> 308 E. 309 310sort_nodes(Ts) -> 311 [setelement(4, T, lists:sort(element(4, T))) || T <- Ts]. 312 313adjust_times([]) -> 314 {0, []}; 315adjust_times([T1 | _]=Ts) -> 316 Base = element(2, T1), 317 {Base, adjust_times(Ts, Base)}. 318 319adjust_times(Ts, Base) -> 320 [setelement(2, adj_tag(T, Base), adjust_time(element(2, T), Base)) || 321 T <- Ts]. 322 323adj_tag({Node, Time, {M, Node2}, Nodes, Extra}=T, Base) -> 324 if 325 M =:= new_resolver; 326 M =:= kill_resolver; 327 M =:= exit_resolver -> 328 {Node, Time, {M, Node2}, Nodes, 329 [adjust_time(hd(Extra), Base) | tl(Extra)]}; 330 true -> 331 T 332 end. 333 334adjust_time(Time, Base) -> 335 musec2sec(timer:now_diff(Time, Base)). 336 337action_nodes({_Node, _Time, {_, Nodes}, _, _}) when is_list(Nodes) -> 338 Nodes; 339action_nodes({_Node, _Time, {_, Node}, _, _}) -> 340 [Node]. 341 342%% Some of the names in global_SUITE.erl are recognized. 343adjust_node(Node) -> 344 case atom_to_list(Node) of 345 "cp" ++ L -> 346 list_to_atom([$c, $p | lists:takewhile(fun is_digit/1, L)]); 347 "test_server" ++ _ -> 348 test_server; 349 "a_2" ++ _ -> 350 a_2; 351 "n_1" ++ _ -> 352 n_1; 353 "n_2" ++ _ -> 354 n_2; 355 "z_2" ++ _ -> 356 z_2; 357 "z_" ++ _ -> 358 z; 359 "b_" ++ _ -> 360 b; 361 "c_external_nodes" ++ _ -> 362 c_external_nodes; 363 _ -> 364 Node 365 end. 366 367is_digit(C) -> 368 (C >= $0) and (C =< $9). 369 370eval(Trace, Fun) -> 371 eval(Trace, {0, 0}, #w{}, Fun). 372 373eval([T | Ts], Time0, S0, Fun) -> 374 Time1 = element(2, T), 375 case is_fresh(S0#w.nodes) of 376 true -> 377 io:format("~p ***************** FRESH *****************~n", 378 [Time1]); 379 false -> 380 ok 381 end, 382 case time_diff(Time1, Time0) > 0 of 383 true -> 384 display_nodes("PAUS", Time1, S0#w.nodes, T); 385 false -> 386 ok 387 end, 388 S = eval_trace(T, S0), 389 Fun(T, S), 390 eval(Ts, Time1, S, Fun); 391eval([], _, S, _Fun) -> 392 {S#w.nodes, lists:usort(S#w.n)}. 393 394%% Old. 395eval_trace({Node, Time, {added,Added}, _Nodes, [_NewNodes,_Abc]}, S0) -> 396 added(Node, Added, Time, S0); 397eval_trace({Node, Time, {added,Added}, _Nodes, []}, S0) -> 398 added(Node, Added, Time, S0); 399 400 401eval_trace({Node, Time, {init, Node}, Nodes, []}, S0) -> 402 init(Node, Nodes, Time, S0); 403eval_trace({Node, Time, {nodedown, DownNode}, Nodes, []}, S0) -> 404 node_down(Node, DownNode, Nodes, Time, S0); 405eval_trace({Node, Time, {extra_nodedown, DownNode}, Nodes, []}, S0) -> 406 node_down(Node, DownNode, Nodes, Time, S0); 407eval_trace({Node, Time, {nodeup, UpNode}, Nodes, []}, S0) -> 408 node_up(Node, UpNode, Nodes, Time, S0); 409eval_trace({Node, Time, {added,Added}, _Nodes, [_NewNodes,_Abc,_Ops]}, S0) -> 410 added(Node, Added, Time, S0); 411eval_trace({Node, Time, {added,Added}, _Nodes, [_Ops]}, S0) -> 412 added(Node, Added, Time, S0); 413eval_trace({Node, Time, {nodes_changed, {New,Old}}, _Nodes, []}, S0) -> 414 nodes_changed(Node, New, Old, Time, S0); 415eval_trace({Node, Time, {ins_name, PNode}, _Nodes, [Name, Pid]}, S0) -> 416 insert_name(Node, PNode, Time, Name, Pid, S0); 417eval_trace({Node, Time, {del_name, PNode}, _Nodes, [Name, Pid]}, S0) -> 418 delete_name(Node, PNode, Time, Name, Pid, S0); 419eval_trace({Node, Time, {ins_name_ext, PNode}, _Nodes, [Name, Pid]}, S0) -> 420 insert_external_name(Node, PNode, Time, Name, Pid, S0); 421eval_trace({Node, Time, {ins_lock, PNode}, _Nodes, [Id, Pid]}, S0) -> 422 insert_lock(Node, PNode, Time, Id, Pid, S0); 423eval_trace({Node, Time, {rem_lock, PNode}, _Nodes, [Id, Pid]}, S0) -> 424 remove_lock(Node, PNode, Time, Id, Pid, S0); 425eval_trace({Node, Time, {locker_succeeded, _}, _Nodes,{_First,_Known}}, S0) -> 426 locker_succeeded(Node, Time, S0); 427eval_trace({Node, Time, {lock_rejected, _}, _Nodes, Known}, S0) -> 428 lock_rejected(Node, Time, Known, S0); 429eval_trace({Node, Time, {locker_failed, _}, _Nodes, {Tried,SoFar}}, S0) -> 430 locker_failed(Node, Time, Tried, SoFar, S0); 431eval_trace({Node, Time, {new_resolver, RNode}, _Nodes, [Tag, ResPid]}, S0) -> 432 new_resolver(Node, Time, RNode, Tag, ResPid, S0); 433eval_trace({Node, Time, {kill_resolver, RNode}, _Nodes, [Tag,_ResPid]}, S0) -> 434 stop_resolver(Node, Time, RNode, Tag, kill, S0); 435eval_trace({Node, Time, {exit_resolver, RNode}, _Nodes, [Tag]}, S0) -> 436 stop_resolver(Node, Time, RNode, Tag, exit, S0); 437eval_trace(_Ignored, S) -> 438io:format("ignored ~p~n", [_Ignored]), 439 S. 440 441init(_Node, [], _Time, S) -> 442 S; 443init(Node, NodesList, Time, S) -> 444 io:format("### ~p ~p: already in nodes(): ~p~n", [Node, Time, NodesList]), 445 S. 446 447node_down(Node, DownNode, NodesList, Time, S0) -> 448 case get_node(Node, S0) of 449 {ok, #node{known = Known, nodes = Nodes}=N} -> 450 case lists:member(DownNode, Nodes) of 451 true -> 452 S1 = case lists:member(DownNode, Known) of 453 true -> 454 S0; 455 false -> 456 io:format("### ~p ~p:~n " 457 "nodedown but unknown ~p~n", 458 [Node, Time, DownNode]), 459 case lists:member(DownNode, Nodes) of 460 true -> 461 io:format("(but note that ~p" 462 " is member of nodes())~n", 463 [DownNode]); 464 false -> 465 ok 466 end, 467 add_spurious(Node, DownNode, S0, Time) 468 end, 469 NewKnown = lists:delete(DownNode, Known), 470 NewNodes = lists:delete(DownNode, Nodes), 471 put_node(N#node{known = NewKnown, nodes = NewNodes}, S1); 472 false -> 473 io:format("### ~p ~p:~n spurious nodedown from ~p~n " 474 "~p~n", [Node, Time, DownNode, NodesList]), 475 NewKnown = lists:delete(DownNode, Known), 476 S1 = put_node(N#node{known = NewKnown,nodes = Nodes}, S0), 477 add_spurious(Node, DownNode, S1, Time) 478 end; 479 not_ok -> 480 io:format("### ~p ~p:~n unknown node got nodedown from ~p~n", 481 [Node, Time, DownNode]), 482 add_spurious(Node, DownNode, S0, Time) 483 end. 484 485node_up(Node, UpNode, NodesList, Time, S) -> 486 case get_node(Node, S) of 487 {ok, #node{nodes = Nodes}=N} -> 488 case lists:member(UpNode, Nodes) of 489 true -> 490 io:format("### ~p ~p:~n spurious nodeup from ~p~n " 491 "~p~n", [Node, Time, UpNode, NodesList]), 492 add_spurious(Node, UpNode, S, Time); 493 false -> 494 put_node(N#node{nodes = lists:sort([UpNode | Nodes])}, S) 495 end; 496 not_ok -> 497 S#w{nodes = [#node{node = Node, nodes = [UpNode]} | S#w.nodes]} 498 end. 499 500added(Node, Added, Time, S0) -> 501 case get_node(Node, S0) of 502 {ok, #node{known = Known, nodes = Nodes}=N} -> 503 case Known -- (Known -- Added) of 504 [] -> 505 S1 = put_node(N#node{known = lists:sort(Added ++ Known), 506 nodes = Nodes}, S0), 507 case lists:member(Node, Added) of 508 true -> 509 io:format("### ~p ~p:~n adding node()" 510 " to known (~p)~n", [Node, Time,Added]), 511 add_spurious(Node, Added, S1, Time); 512 false -> 513 S1 514 end; 515 AK -> 516 io:format("### ~p ~p:~n added already known ~p~n", 517 [Node, Time, AK]), 518 S1 = put_node(N#node{known = lists:usort(Added ++ Known), 519 nodes = Nodes}, S0), 520 add_spurious(Node, AK, S1, Time) 521 end; 522 not_ok -> 523 io:format("### ~p ~p:~n unknown node got added ~p~n", 524 [Node, Time, Added]), 525 S1 = S0#w{nodes = [#node{node = Node, known = Added} | 526 S0#w.nodes]}, 527 add_spurious(Node, Added, S1, Time) 528 end. 529 530nodes_changed(Node, New, Old, Time, S) -> 531 io:format("### ~p ~p:~n nodes changed, new are ~p, old are ~p~n", 532 [Node, Time, New, Old]), 533 S. 534 535insert_external_name(Node, PNode, Time, Name, Pid, S) -> 536 insert_name(Node, PNode, Time, Name, Pid, S). 537 538insert_name(Node, PNode, Time, Name, Pid, S0) -> 539 RegName = {Name, Pid, PNode}, 540 case get_node(Node, S0) of 541 {ok, #node{names = Names}=N} -> 542 case lists:keysearch(Name, 1, Names) of 543 {value, {Name, OldPid, OldPNode}} -> 544 io:format("### ~p ~p:~n name ~p already registered " 545 "for ~p on ~p~n", 546 [Node, Time, Name, OldPid, OldPNode]), 547 add_spurious(Node, [PNode], S0, Time); 548 false -> 549 case lists:keysearch(Pid, 2, Names) of 550 {value, {OldName, Pid, OldPNode}} -> 551 io:format("### ~p ~p:~n pid ~p already " 552 "registered as ~p on ~p~n", 553 [Node, Time, Pid, OldName, OldPNode]), 554 add_spurious(Node, [PNode], S0, Time); 555 false -> 556 put_node(N#node{names = [RegName | Names]}, S0) 557 end 558 end; 559 not_ok -> 560 io:format("### ~p ~p:~n unknown node registered ~p for ~p " 561 "on ~p~n", [Node, Time, Name, Pid, PNode]), 562 Known = add_to_known(Node, PNode, []), 563 N = #node{node = Node, known = Known, names = [RegName]}, 564 S1 = S0#w{nodes = [N | S0#w.nodes]}, 565 add_spurious(Node, [PNode], S1, Time) 566 end. 567 568delete_name(Node, PNode, Time, Name, Pid, S0) -> 569 case get_node(Node, S0) of 570 {ok, #node{names = Names}=N} -> 571 case lists:keysearch(Name, 1, Names) of 572 {value, {Name, Pid, PNode}} -> 573 NewNames = lists:keydelete(Name, 1, Names), 574 put_node(N#node{names = NewNames}, S0); 575 {value, {Name, Pid2, PNode2}} -> % bad log 576 io:format("### ~p ~p:~n name ~p not registered " 577 "for ~p on ~p but for ~p on ~p~n", 578 [Node, Time, Name, Pid, PNode, Pid2, PNode2]), 579 add_spurious(Node, [PNode], S0, Time); 580 false -> 581 io:format("### ~p ~p:~n name ~p not registered " 582 "for ~p on ~p~n", 583 [Node, Time, Name, Pid, PNode]), 584 add_spurious(Node, [PNode], S0, Time) 585 end; 586 not_ok -> 587 io:format("### ~p ~p:~n unknown node deleted ~p for ~p on ~p~n", 588 [Node, Time, Name, Pid, PNode]), 589 Known = add_to_known(Node, PNode, []), 590 N = #node{node = Node, known = Known}, 591 S1 = S0#w{nodes = [N | S0#w.nodes]}, 592 add_spurious(Node, [PNode], S1, Time) 593 end. 594 595insert_lock(Node, PNode, Time, Id, Pid, S0) -> 596 Lock = {Pid, PNode}, 597 case get_node(Node, S0) of 598 {ok, #node{locks = NLocks}=N} -> 599 case lists:keysearch(Id, 1, NLocks) of 600 {value, {Id, OldLocks}} -> 601 case lists:member(Lock, OldLocks) of 602 true -> 603 io:format("### ~p ~p:~n lock ~p already set " 604 "for ~p on ~p~n", 605 [Node, Time, Id, Pid, PNode]), 606 %% This is not so strange, actually. 607 add_spurious(Node, [PNode], S0, Time); 608 false -> 609 NewLocks = {Id, [Lock | OldLocks]}, 610 Ls = lists:keyreplace(Id, 1, NLocks, NewLocks), 611 put_node(N#node{locks = Ls}, S0) 612 end; 613 false -> 614 put_node(N#node{locks = [{Id,[Lock]}|N#node.locks]}, S0) 615 end; 616 not_ok -> 617 Known = add_to_known(Node, PNode, []), 618 N = #node{node = Node, known = Known, locks = [{Id, [Lock]}]}, 619 S1 = S0#w{nodes = [N | S0#w.nodes]}, 620 if 621 Node =/= PNode -> 622 io:format("### ~p ~p:~n unknown pid ~p locked ~p on " 623 "~p~n", [Node, Time, Pid, Id, PNode]), 624 add_spurious(Node, [PNode], S1, Time); 625 true -> 626 S1 627 end 628 end. 629 630remove_lock(Node, PNode, Time, Id, Pid, S0) -> 631 Lock = {Pid, PNode}, 632 case get_node(Node, S0) of 633 {ok, #node{locks = NLocks}=N} -> 634 case lists:keysearch(Id, 1, NLocks) of 635 {value, {Id, OldLocks}} -> 636 case lists:member(Lock, OldLocks) of 637 true -> 638 NewLocks = lists:delete(Lock, OldLocks), 639 Ls = case NewLocks of 640 [] -> 641 lists:keydelete(Id, 1, NLocks); 642 _ -> 643 lists:keyreplace(Id, 1, NLocks, 644 {Id, NewLocks}) 645 end, 646 put_node(N#node{locks = Ls}, S0); 647 false -> 648 io:format("### ~p ~p:~n lock ~p not set " 649 "by ~p on ~p~n", 650 [Node, Time, Id, Pid, PNode]), 651 add_spurious(Node, [PNode], S0, Time) 652 end; 653 false -> 654 io:format("### ~p ~p:~n lock ~p not set " 655 "by ~p on ~p~n", 656 [Node, Time, Id, Pid, PNode]), 657 add_spurious(Node, [PNode], S0, Time) 658 end; 659 not_ok -> 660 io:format("### ~p ~p:~n ~p unlocked ~p on unknown node ~p~n", 661 [Node, Time, Pid, Id, PNode]), 662 Known = add_to_known(Node, PNode, []), 663 N = #node{node = Node, known = Known}, 664 S1 = S0#w{nodes = [N | S0#w.nodes]}, 665 add_spurious(Node, [PNode], S1, Time) 666 end. 667 668%% This is just statistics... 669locker_succeeded(Node, Time, S0) -> 670 case get_node(Node, S0) of 671 {ok, #node{n_locks = {Ok,Boss,NodeX,Bad}}=N} -> 672 put_node(N#node{n_locks = {Ok+1,Boss,NodeX,Bad}}, S0); 673 not_ok -> 674 io:format("### ~p ~p:~n unknown node's locker succeeded~n", 675 [Node, Time]), 676 add_spurious(Node, [Node], S0, Time) 677 end. 678 679lock_rejected(Node, Time, _Known, S0) -> 680 case get_node(Node, S0) of 681 {ok, #node{rejected = Rej}=N} -> 682 put_node(N#node{rejected = Rej+1}, S0); 683 not_ok -> 684 io:format("### ~p ~p:~n unknown node's lock rejected~n", 685 [Node, Time]), 686 add_spurious(Node, [Node], S0, Time) 687 end. 688 689locker_failed(Node, Time, Tried, SoFar, S0) -> 690 case get_node(Node, S0) of 691 {ok, #node{known = Known, n_locks = {Ok,Boss,NodeX,Bad}}=N} -> 692 TheBoss = lists:max([Node | Known]), 693 Cheap = (Tried =:= [TheBoss]), 694 RatherCheap = ((SoFar -- [Node, TheBoss]) =:= []) and 695 ((Tried -- [Node, TheBoss]) =/= []), 696 if 697 Cheap -> 698 put_node(N#node{n_locks = {Ok,Boss+1,NodeX,Bad}}, S0); 699 RatherCheap -> 700 put_node(N#node{n_locks = {Ok,Boss,NodeX+1,Bad}}, S0); 701 true -> 702 put_node(N#node{n_locks = {Ok,Boss,NodeX,Bad+1}}, S0) 703 end; 704 not_ok -> 705 io:format("### ~p ~p:~n unknown node's locker failed~n", 706 [Node, Time]), 707 add_spurious(Node, [Node], S0, Time) 708 end. 709 710new_resolver(Node, Time, ResNode, Tag, ResPid, S0) -> 711 case get_node(Node, S0) of 712 {ok, #node{resolvers = Rs}=N} -> 713 put_node(N#node{resolvers = [{ResNode, Tag, ResPid} | Rs]}, S0); 714 not_ok -> 715 io:format("### ~p ~p:~n resolver created for unknown node~n", 716 [Node, Time]), 717 add_spurious(Node, [Node], S0, Time) 718 end. 719 720stop_resolver(Node, Time, ResNode, Tag, How, S0) -> 721 case get_node(Node, S0) of 722 {ok, #node{resolvers = Rs}=N} -> 723 case lists:keysearch(Tag, 2, Rs) of 724 {value, {ResNode, Tag, _ResPid}} -> 725 NewRs = lists:keydelete(Tag, 2, Rs), 726 put_node(N#node{resolvers = NewRs}, S0); 727 false -> 728 case lists:keysearch(ResNode, 1, Rs) of 729 {value, {ResNode, _Tag2, _ResPid2}} -> 730 NewRs = lists:keydelete(ResNode, 1, Rs), 731 put_node(N#node{resolvers = NewRs}, S0); 732 false when How =:= exit -> 733 io:format("### ~p ~p:~n there is no resolver " 734 "with tag ~p on node ~p~n", 735 [Node, Time, Tag, ResNode]), 736 add_spurious(Node, [ResNode], S0, Time); 737 false when How =:= kill -> 738 S0 739 end 740 end; 741 not_ok -> 742 io:format("### ~p ~p:~n resolver stopped for unknown node~n", 743 [Node, Time]), 744 add_spurious(Node, [Node], S0, Time) 745 end. 746 747add_to_known(Node, NodeToAdd, Known) -> 748 if 749 Node =:= NodeToAdd -> 750 Known; 751 true -> 752 lists:sort([NodeToAdd | Known]) 753 end. 754 755get_node(Node, S) -> 756 case lists:keysearch(Node, #node.node, S#w.nodes) of 757 {value, N} -> 758 {ok, N}; 759 false -> 760 not_ok 761 end. 762 763put_node(#node{node = Node, known = [], nodes = [], locks = [], names = [], 764 n_locks = {0,0,0,0}}, 765 S) -> 766 S#w{nodes = lists:keydelete(Node, #node.node, S#w.nodes)}; 767put_node(N, S) -> 768 S#w{nodes = lists:keyreplace(N#node.node, #node.node, S#w.nodes, N)}. 769 770is_fresh(#node{known = [], nodes = [], locks = [], names = []}) -> 771 true; 772is_fresh(#node{}) -> 773 false; 774is_fresh([]) -> 775 true; 776is_fresh([N | Ns]) -> 777 is_fresh(N) andalso is_fresh(Ns). 778 779add_spurious(Node, ActionNodes, S, Time) when is_list(ActionNodes) -> 780 S#w{n = [{{Node,N},Time}|| N <- ActionNodes] ++ S#w.n}; 781add_spurious(Node, ActionNode, S, Time) -> 782 add_spurious(Node, [ActionNode], S, Time). 783 784messages(D, Base, End) -> 785 messages1(no_info(D), no_info), 786 messages1(resolvers(D, Base, End), resolvers), 787 messages1(syncers(D), syncers). 788 789messages1(M, ST) -> 790 [foo || {Node, T} <- M, 791 ok =:= io:format(ms(ST), [Node, T])]. 792 793ms(no_info) -> 794 "~p: ~p~n"; 795ms(resolvers) -> 796 "~p: resolvers ~p~n"; 797ms(syncers) -> 798 "~p: syncers ~p~n". 799 800no_info(D) -> 801 [{Node,no_info} || {Node, no_info} <- D]. 802 803resolvers(D, Base, End) -> 804 [{Node, 805 [{N,adjust_time(T, Base),P} || {N, T, P} <- Rs, T < End]} || 806 {Node, {info,State}} <- D, 807 is_record(State, state), 808 [] =/= (Rs = (state(State))#state.resolvers)]. 809 810syncers(D) -> 811 [{Node,Ss} || {Node, {info,State}} <- D, 812 is_record(State, state), 813 [] =/= (Ss = (state(State))#state.syncers)]. 814 815net_kernel_nodes(NodeTrace) -> 816 [{Node, nkn(Trace, [])} || {Node, Trace} <- NodeTrace]. 817 818nkn([], _Nodes) -> 819 []; 820nkn([{Node, Time, _Message, Ns, _X} | Ts], Nodes) -> 821 {NewS, _, OldS} = sofs:symmetric_partition(sofs:set(Ns), sofs:set(Nodes)), 822 New = sofs:to_external(NewS), 823 Old = sofs:to_external(OldS), 824 [{Node, Time, {newnode, N}, []} || N <- New] ++ 825 [{Node, Time, {oldnode, N}, []} || N <- Old] ++ 826 nkn(Ts, (Nodes -- Old) ++ New). 827 828negotiations(Trace) -> 829 Ns = [{Node,T,Added,X} || 830 {Node,T,{added,Added},_Nodes,X} <- Trace], 831 Pass = [{passive,Node,T,Added} || 832 {Node,T,Added,[_Ops]} <- Ns], 833 Act = [{active,Node,T,Other,Added,NewNodes} || 834 {Node,T,Added,[{new_nodes,[Other|_]=NewNodes},_Abcast,_Ops]} <- Ns], 835 Act ++ Pass. 836 837show_spurious(NodeTrace, Spurious) -> 838 Pairs = [{Node,ActionNode} || {{Node,ActionNode}, _Time} <- Spurious], 839 S = sofs:restriction(sofs:relation(NodeTrace), sofs:set(Pairs)), 840 [foo || 841 {{{Node,ANode},Times}, 842 {{Node,ANode},Ts}} <- lists:zip(family(Spurious), 843 sofs:to_external(S)), 844 show_spurious(Node, ANode, Times, lists:keysort(2, Ts))]. 845 846show_spurious(Node, ActionNode, Times, Ts) -> 847 io:format("** Actions for ~p on node ~p **~n", [ActionNode, Node]), 848 lists:map(fun(T) -> spurious(Node, T, Times) end, Ts), 849 io:format("-- End of actions for ~p on node ~p --~n", [ActionNode, Node]), 850 true. 851 852spurious(Node, Trace, Times) -> 853 As = case Trace of 854 {Node, _T0, {init, Node}, _Nodes, _} -> 855 init; % should not happen, I guess 856 {Node, _T0, {nodedown, _ActionNode}, _Nodes, _} -> 857 nodedown; 858 {Node, _T0, {extra_nodedown, _ActionNode}, _Nodes, _} -> 859 extra_nodedown; 860 {Node, _T0, {nodeup, _ActionNode}, _Nodes, _} -> 861 nodeup; 862 {Node, _T0, {added, Added}, _Nodes, [_Ops]} -> 863 {passive, Added}; 864 {Node, _T0, {added, Added}, _Nodes, [_NewNodes,_AbCast,_Ops]} -> 865 {negotiator, Added}; 866 {Node, _T0, {ins_lock, PNode}, _Nodes, [Id, Pid]} -> 867 {insert_lock, [Id, Pid, PNode]}; 868 {Node, _T0, {rem_lock, PNode}, _Nodes, [Id, Pid]} -> 869 {remove_lock, [Id, Pid, PNode]}; 870 {Node, _T0, {ins_name, PNode}, _Nodes, [Name, Pid]} -> 871 {insert_name, [Name, Pid, PNode]}; 872 {Node, _T0, {del_name, PNode}, _Nodes, [Name, Pid]} -> 873 {insert_name, [Name, Pid, PNode]}; 874 {Node, _T0, {nodes_changed, CNode}, _Nodes, []} -> 875 {nodes_changed, [CNode]}; 876 {Node, _T0, {Any, Some}, _Nodes, X} -> 877 {Any, [Some | X]} 878 end, 879 T = element(2, Trace), 880 _Nodes2 = element(4, Trace), 881 TS = ["(spurious)" || lists:member(T, Times)], 882 io:format("~p: ~p ~s~n", [T, As, TS]), 883% io:format(" ~w~n", [_Nodes2]), 884 ok. 885 886display_nodes(Why, Time, Nodes) -> 887 display_nodes(Why, Time, Nodes, none). 888 889display_nodes(Why, Time, Nodes, LastTrace) -> 890 io:format("~p **** ~s ****~n", [Time, Why]), 891 {OkL, BossL, NodeXL, BadL} = unzip4([L || #node{n_locks = L} <- Nodes]), 892 [NOk, NBoss, NNodeX, NBad] = 893 [lists:sum(L) || L <- [OkL, BossL, NodeXL, BadL]], 894 Rejected = lists:sum([Rej || #node{rejected = Rej} <- Nodes]), 895 io:format("Locks: (~w+~w+~w=~w)/~w, ~w of ~w rejected~n", 896 [NOk, NBoss, NNodeX, NOk+NBoss+NNodeX, NOk+NBoss+NNodeX+NBad, 897 Rejected, NOk]), 898 lists:foreach(fun(#node{node = Node, known = Known, nodes = Ns, 899 locks = Locks, names = Names, 900 n_locks = {Ok, Boss, NodeX, Bad}, 901 resolvers = Resolvers0, 902 rejected = Rej}) -> 903 NodeL = io_lib:format("~p: ",[Node]), 904 io:format("~sknown ~p~n", [NodeL, Known]), 905 Sp = spaces(NodeL), 906 case Ns =:= Known of 907 true -> ok; 908 false -> display_list(Sp, nodes, Ns) 909 end, 910 display_list(Sp, locks, Locks), 911 display_list(Sp, names, lists:sort(Names)), 912 Resolvers = lists:sort(Resolvers0), 913 _ResNs = [R || {R,_,_} <- Resolvers], 914 %% Should check trace on this node (Node) only: 915 New = [N || {_,_,{nodeup,N},_,_} <- [LastTrace]], 916 _ResAllowed = (Ns -- New) -- Known, 917%% Displays too much junk. 918% case ResAllowed =:= ResNs of 919% true -> ok; 920% false -> display_list(Sp, resol, Resolvers) 921% end, 922 %% This is less bulky: 923 case Known =:= Ns of 924 true -> display_list(Sp, resol, Resolvers); 925 false -> ok 926 end, 927 case {Ok, Boss, NodeX, Bad} of 928 {0, 0, 0, 0} -> ok; 929 _ -> io:format("~slocks (~w+~w+~w=~w)/~w, " 930 "~w of ~w rejected~n", 931 [Sp, Ok, Boss, NodeX, 932 Ok+Boss+NodeX,Ok+Boss+NodeX+Bad, 933 Rej, Ok]) 934 end 935 end, lists:keysort(#node.node, Nodes)), 936 io:format("\n"). 937 938display_list(_S, _What, []) -> 939 ok; 940display_list(S, What, L) -> 941 io:format("~s~p ~p~n", [S, What, L]). 942 943spaces(Iolist) -> 944 lists:duplicate(iolist_size(Iolist), $\s). 945 946family(R) -> 947 sofs:to_external(sofs:relation_to_family(sofs:relation(R))). 948 949time_diff({S1,MyS1}, {S0,MyS0}) -> 950 ((S1*1000000+MyS1) - (S0*1000000+MyS0)) div 1000000. 951 952musec2sec(T) -> 953 S = T div 1000000, 954 M = (T - S * 1000000), 955 {S, M}. 956 957%%% Options 958 959options(Options, Keys) when is_list(Options) -> 960 options(Options, Keys, []); 961options(Option, Keys) -> 962 options([Option], Keys, []). 963 964options(Options0, [Key | Keys], L) when is_list(Options0) -> 965 Options = case lists:member(Key, Options0) of 966 true -> 967 [atom_option(Key) | lists:delete(Key, Options0)]; 968 false -> 969 Options0 970 end, 971 V = case lists:keysearch(Key, 1, Options) of 972 {value, {show_state, From, To}} when is_integer(From), From >= 0, 973 is_integer(To), To >= From -> 974 {ok, {{From,0}, {To,0}}}; 975 {value, {show_state, {From, FromMusec}, 976 {To, ToMusec}}} when is_integer(From), 977 From >= 0, 978 is_integer(To), 979 To >= From, 980 FromMusec >= 0, 981 FromMusec =< 999999, 982 ToMusec >= 0, 983 ToMusec =< 999999 -> 984 {ok, {{From,FromMusec}, {To,ToMusec}}}; 985 {value, {show_state, false}} -> 986 {value, default_option(show_state)}; 987 {value, {show_trace, Bool}} when Bool; not Bool -> 988 {ok, Bool}; 989 {value, {Key, _}} -> 990 badarg; 991 false -> 992 Default = default_option(Key), 993 {ok, Default} 994 end, 995 case V of 996 badarg -> 997 badarg; 998 {ok, Value} -> 999 NewOptions = lists:keydelete(Key, 1, Options), 1000 options(NewOptions, Keys, [Value | L]) 1001 end; 1002options([], [], L) -> 1003 lists:reverse(L); 1004options(_Options, _, _L) -> 1005 badarg. 1006 1007default_option(show_state) -> {{0,0}, {0,0}}; 1008default_option(show_trace) -> true. 1009 1010atom_option(show_state) -> 1011 {show_state, 0, 1 bsl 28}; 1012atom_option(show_trace) -> 1013 {show_trace, true}; 1014atom_option(_) -> 1015 erlang:error(program_error, []). 1016 1017unzip4(Ts) -> unzip4(Ts, [], [], [], []). 1018 1019unzip4([{X, Y, Z, W} | Ts], Xs, Ys, Zs, Ws) -> 1020 unzip4(Ts, [X | Xs], [Y | Ys], [Z | Zs], [W | Ws]); 1021unzip4([], Xs, Ys, Zs, Ws) -> 1022 {lists:reverse(Xs), lists:reverse(Ys), 1023 lists:reverse(Zs), lists:reverse(Ws)}. 1024 1025