observer: Add SASL log view for processes

Add a new menu to toggle log view.
Disabled by default.
Disabled if rb_server already started on observed node,
in order not to interfere with somebody else.
If enabled, add a tab in process view where log entries
related to pid process are shown.
Need an observed node with at least a version R16B2,
due to the use of newly capability to rb to write into
a file descriptor (on the observing node).

5 files changed, 248 insertions, 23 deletions

diff --git a/lib/observer/doc/src/observer_ug.xml b/lib/observer/doc/src/observer_ug.xml
index 62f99c5210..fcb42f6c31 100644
--- a/lib/observer/doc/src/observer_ug.xml
+++ b/lib/observer/doc/src/observer_ug.xml
@@ -104,6 +104,29 @@
     <note>
       <p><em>Reds</em> can be presented as accumulated values or as values since last update.</p>
     </note>
+    <p><c>Process info</c> open a detailed information window on the selected process.
+    <taglist>
+      <tag>Process Information</tag>
+      <item>Shows the process information.</item>
+      <tag>Messages</tag>
+      <item>Shows the process messages.</item>
+      <tag>Dictionary</tag>
+      <item>Shows the process dictionary.</item>
+      <tag>Stack Trace</tag>
+      <item>Shows the process current stack trace.</item>
+      <tag>State</tag>
+      <item>Show the process state.</item>
+      <tag>Log</tag>
+      <item>If enabled and available, show the process SASL log entries.</item>
+    </taglist>
+    <note>
+      <p><c>Log</c> needs SASL application to be started on the observed node, with log_mf_h as log handler.
+      The Observed node must be R16B02 or higher.
+      <c>rb</c> server must not be started on the observed node when clicking on menu 'Log/Toggle log view'.
+      <c>rb</c> server will be stopped on the observed node when exiting or changing observed node.
+      </p>
+    </note>
+    </p>
     <p><c>Trace Processes</c> will add the selected process identifiers to the <c>Trace Overview</c> view and the
     node the processes reside on will be added as well.
     <c>Trace Named Processes</c> will add the registered name of processes. This can be useful
diff --git a/lib/observer/src/observer_html_lib.erl b/lib/observer/src/observer_html_lib.erl
index c279218707..53197078cf 100644
--- a/lib/observer/src/observer_html_lib.erl
+++ b/lib/observer/src/observer_html_lib.erl
@@ -60,7 +60,8 @@ expandable_term_body(Heading,[],_Tab) ->
 	 "StackDump"  -> "No stack dump was found";
 	 "Dictionary" -> "No dictionary was found";
 	 "ProcState"  -> "Information could not be retrieved,"
-			     " system messages may not be handled by this process."
+			     " system messages may not be handled by this process.";
+         "SaslLog"    -> "No log entry was found"
      end];
 expandable_term_body(Heading,Expanded,Tab) ->
     Attr = "BORDER=0 CELLPADDING=0 CELLSPACING=1 WIDTH=100%",
@@ -102,7 +103,10 @@ expandable_term_body(Heading,Expanded,Tab) ->
 		    element(1, lists:mapfoldl(fun(Entry, Even) ->
 						      {proc_state(Tab, Entry,Even),
 						       not Even}
-					      end, true, Expanded))]);
+					      end, true, Expanded))]);         
+     "SaslLog"  ->
+             table(Attr,
+                   [tr("BGCOLOR=white",[td("ALIGN=left", pre(href_proc_port(Expanded)))])]) ;
 	 _ ->
 	     table(Attr,
 		   [tr(
diff --git a/lib/observer/src/observer_procinfo.erl b/lib/observer/src/observer_procinfo.erl
index 8e8a37fc93..a8512894f9 100644
--- a/lib/observer/src/observer_procinfo.erl
+++ b/lib/observer/src/observer_procinfo.erl
@@ -43,6 +43,8 @@
 
 -record(worker, {panel, callback}).
 
+-record(io, {rdata=""}).
+
 start(Process, ParentFrame, Parent) ->
     wx_object:start_link(?MODULE, [Process, ParentFrame, Parent], []).
 
@@ -69,6 +71,10 @@ init([Pid, ParentFrame, Parent]) ->
 	DictPage    = init_panel(Notebook, "Dictionary", [Pid,Table], fun init_dict_page/3),
 	StackPage   = init_panel(Notebook, "Stack Trace", [Pid], fun init_stack_page/2),
 	StatePage   = init_panel(Notebook, "State", [Pid,Table], fun init_state_page/3),
+        Ps = case gen_server:call(observer, log_status) of
+		 true  -> [init_panel(Notebook, "Log", [Pid,Table], fun init_log_page/3)];
+		 false -> []
+	     end,
 
 	wxFrame:connect(Frame, close_window),
 	wxMenu:connect(Frame, command_menu_selected),
@@ -78,7 +84,7 @@ init([Pid, ParentFrame, Parent]) ->
 		       pid=Pid,
 		       frame=Frame,
 		       notebook=Notebook,
-		       pages=[ProcessPage,MessagePage,DictPage,StackPage,StatePage],
+		       pages=[ProcessPage,MessagePage,DictPage,StackPage,StatePage|Ps],
 		       expand_table=Table
 		      }}
     catch error:{badrpc, _} ->
@@ -327,6 +333,26 @@ fetch_state_info2(Pid, M) ->
 	{badrpc,{'EXIT',{timeout, _}}} -> []
     end.
 
+init_log_page(Parent, Pid, Table) ->
+    Win = observer_lib:html_window(Parent),
+    Update = fun() ->
+		     Fd = spawn_link(fun() -> io_server() end),
+		     rpc:call(node(Pid), rb, rescan, [[{start_log, Fd}]]),
+		     rpc:call(node(Pid), rb , grep, [local_pid_str(Pid)]),
+		     Logs = io_get_data(Fd),
+		     %% Replace remote local pid notation to global notation
+		     Pref = global_pid_node_pref(Pid),
+		     ExpPid = re:replace(Logs,"<0\.","<" ++ Pref ++ ".",[global, {return, list}]),
+		     %% Try to keep same look by removing blanks at right of rewritten PID
+		     NbBlanks = length(Pref) - 1,
+		     Re = "(<" ++ Pref ++ "\.[^>]{1,}>)[ ]{"++ integer_to_list(NbBlanks) ++ "}",
+		     Look = re:replace(ExpPid, Re, "\\1", [global, {return, list}]),
+		     Html = observer_html_lib:expandable_term("SaslLog", Look, Table),
+		     wxHtmlWindow:setPage(Win, Html)
+	     end,
+    Update(),
+    {Win, Update}.
+
 create_menus(MenuBar) ->
     Menus = [{"File", [#create_menu{id=?wxID_CLOSE, text="Close"}]},
 	     {"View", [#create_menu{id=?REFRESH, text="Refresh\tCtrl-R"}]}],
@@ -409,3 +435,55 @@ filter_monitor_info() ->
 	    Ms = proplists:get_value(monitors, Data),
 	    [Pid || {process, Pid} <- Ms]
     end.
+
+local_pid_str(Pid) ->
+    %% observer can observe remote nodes
+    %% There is no function to get the local
+    %% pid from the remote pid ...
+    %% So grep will fail to find remote pid in remote local log.
+    %% i.e. <4589.42.1> will not be found, but <0.42.1> will
+    %% Let's replace first integer by zero
+    "<0" ++ re:replace(pid_to_list(Pid),"\<([0-9]{1,})","",[{return, list}]).
+
+global_pid_node_pref(Pid) ->
+    %% Global PID node prefix : X of <X.Y.Z>
+    string:strip(string:sub_word(pid_to_list(Pid),1,$.),left,$<).
+    
+
+io_get_data(Pid) ->
+    Pid ! {self(), get_data_and_close},
+    receive
+       {Pid, data, Data} ->  lists:flatten(Data)
+    end.
+
+io_server() ->
+    io_server(#io{}).
+
+io_server(State) ->
+    receive
+       {io_request, From, ReplyAs, Request} ->
+           case io_request(Request,State) of
+               {Tag, Reply, NewState} when Tag =:= ok; Tag =:= error ->
+                   From ! {io_reply, ReplyAs, Reply},
+                   io_server(NewState);
+               {stop, Reply, _NewState} ->
+                   From ! {io_reply, ReplyAs, Reply},
+                   exit(Reply)
+           end;
+       {Pid, get_data_and_close} ->
+           Pid ! {self(), data, lists:reverse(State#io.rdata)},
+           normal;
+       _Unknown ->
+           io:format("~p: Unknown msg: ~p ~n",[?LINE, _Unknown]),
+           io_server(State)
+    end.
+
+io_request({put_chars, _Encoding, Chars}, State = #io{rdata=Data}) ->
+    {ok, ok, State#io{rdata=[Chars|Data]}};
+io_request({put_chars, Encoding, Module, Function, Args}, State) ->
+    try        io_request({put_chars, Encoding, apply(Module, Function, Args)}, State)
+    catch _:_ -> {error, {error,Function}, State}
+    end;
+io_request(Req, State) ->
+    io:format("~p: Unknown req: ~p ~n",[?LINE, Req]),
+    State.
diff --git a/lib/observer/src/observer_wx.erl b/lib/observer/src/observer_wx.erl
index c86f5ea916..54c4092a78 100644
--- a/lib/observer/src/observer_wx.erl
+++ b/lib/observer/src/observer_wx.erl
@@ -37,6 +37,7 @@
 -define(ID_CONNECT, 2).
 -define(ID_NOTEBOOK, 3).
 -define(ID_CDV,      4).
+-define(ID_LOGVIEW, 5).
 
 -define(FIRST_NODES_MENU_ID, 1000).
 -define(LAST_NODES_MENU_ID,  2000).
@@ -60,7 +61,8 @@
 	 active_tab,
 	 node,
 	 nodes,
-	 prev_node=""
+	 prev_node="",
+	 log = false
 	}).
 
 start() ->
@@ -215,14 +217,17 @@ handle_event(#wx{event=#wxNotebook{type=command_notebook_page_changing}},
 	    {noreply, State#state{active_tab=Pid}}
     end;
 
-handle_event(#wx{event = #wxClose{}}, State) ->
-    {stop, normal, State};
-
 handle_event(#wx{id = ?ID_CDV, event = #wxCommand{type = command_menu_selected}}, State) ->
     spawn(crashdump_viewer, start, []),
     {noreply, State};
 
-handle_event(#wx{id = ?wxID_EXIT, event = #wxCommand{type = command_menu_selected}}, State) ->
+handle_event(#wx{event = #wxClose{}}, #state{log=LogOn} = State) ->
+    LogOn andalso rpc:block_call(State#state.node, rb, stop, []),
+    {stop, normal, State};
+
+handle_event(#wx{id = ?wxID_EXIT, event = #wxCommand{type = command_menu_selected}},
+	     #state{log=LogOn} = State) ->
+    LogOn andalso rpc:block_call(State#state.node, rb, stop, []),
     {stop, normal, State};
 
 handle_event(#wx{id = ?wxID_HELP, event = #wxCommand{type = command_menu_selected}}, State) ->
@@ -300,12 +305,42 @@ handle_event(#wx{id = ?ID_PING, event = #wxCommand{type = command_menu_selected}
 	       end,
     {noreply, UpdState};
 
-handle_event(#wx{id = Id, event = #wxCommand{type = command_menu_selected}}, State)
-  when Id > ?FIRST_NODES_MENU_ID, Id < ?LAST_NODES_MENU_ID ->
+handle_event(#wx{id = ?ID_LOGVIEW, event = #wxCommand{type = command_menu_selected}},
+	     #state{frame = Frame, log = PrevLog, node = Node} = State) ->
+    try
+	ok = ensure_sasl_started(Node),
+	ok = ensure_mf_h_handler_used(Node),
+	ok = ensure_rb_mode(Node, PrevLog),
+	case PrevLog of
+	    false ->
+		rpc:block_call(Node, rb, start, []),
+		set_status("Observer - " ++ atom_to_list(Node) ++ " (rb_server started)"),
+		{noreply, State#state{log=true}};
+	    true ->
+		rpc:block_call(Node, rb, stop, []),
+		set_status("Observer - " ++ atom_to_list(Node) ++ " (rb_server stopped)"),
+		{noreply, State#state{log=false}}
+	end
+    catch
+	throw:Reason ->
+	    create_txt_dialog(Frame, Reason, "Log view status", ?wxICON_ERROR),
+	    {noreply, State}
+    end;
 
-    Node = lists:nth(Id - ?FIRST_NODES_MENU_ID, State#state.nodes),
-    UpdState = change_node_view(Node, State),
-    {noreply, UpdState};
+handle_event(#wx{id = Id, event = #wxCommand{type = command_menu_selected}},
+	     #state{nodes= Ns , node = PrevNode, log = PrevLog} = State)
+  when Id > ?FIRST_NODES_MENU_ID, Id < ?LAST_NODES_MENU_ID ->
+    Node = lists:nth(Id - ?FIRST_NODES_MENU_ID, Ns),
+    %% Close rb_server only if another node than current one selected
+    LState = case PrevLog of
+		 true  -> case Node == PrevNode of
+			      false -> rpc:block_call(PrevNode, rb, stop, []),
+				       State#state{log=false} ;
+			      true  -> State
+			  end;
+		 false -> State
+             end,
+    {noreply, change_node_view(Node, LState)};
 
 handle_event(Event, State) ->
     Pid = get_active_pid(State),
@@ -340,6 +375,9 @@ handle_call(stop, _, State = #state{frame = Frame}) ->
     wxFrame:destroy(Frame),
     {stop, normal, ok, State};
 
+handle_call(log_status, _From, State) ->
+    {reply, State#state.log, State};
+
 handle_call(_Msg, _From, State) ->
     {reply, ok, State}.
 
@@ -422,8 +460,7 @@ return_to_localnode(Frame, Node) ->
     end.
 
 create_txt_dialog(Frame, Msg, Title, Style) ->
-    MD = wxMessageDialog:new(Frame, Msg, [{style, Style}]),
-    wxMessageDialog:setTitle(MD, Title),
+    MD = wxMessageDialog:new(Frame, Msg, [{style, Style}, {caption,Title}]),
     wxDialog:showModal(MD),
     wxDialog:destroy(MD).
 
@@ -569,17 +606,19 @@ default_menus(NodesMenuItems) ->
 		   false -> {"Nodes", NodesMenuItems ++
 				 [#create_menu{id = ?ID_CONNECT, text = "Enable distribution"}]}
 	       end,
+    LogMenu =  {"Log", [#create_menu{id = ?ID_LOGVIEW, text = "Toggle log view"}]},
     case os:type() =:= {unix, darwin} of
 	false ->
 	    FileMenu = {"File", [CDV, Quit]},
 	    HelpMenu = {"Help", [About,Help]},
-	    [FileMenu, NodeMenu, HelpMenu];
+	    [FileMenu, NodeMenu, LogMenu, HelpMenu];
 	true ->
 	    %% On Mac quit and about will be moved to the "default' place
 	    %% automagicly, so just add them to a menu that always exist.
 	    %% But not to the help menu for some reason
-	    {Tag, Menus} = FileMenu,
-	    [{Tag, Menus ++ [About]}, NodeMenu, {"&Help", [Help]}]
+
+	    {Tag, Menus} = NodeMenu,
+	    [{Tag, Menus ++ [Quit,About]}, LogMenu, {"&Help", [Help]}]
     end.
 
 clean_menus(Menus, MenuBar) ->
@@ -658,3 +697,59 @@ update_node_list(State = #state{menubar=MenuBar}) ->
 	   end,
     observer_lib:create_menu_item(Dist, NodeMenu, Index),
     State#state{nodes = Nodes}.
+
+ensure_sasl_started(Node) ->
+   %% is sasl started ?
+   Apps = rpc:block_call(Node, application, which_applications, []),
+   case lists:keyfind(sasl, 1, Apps) of
+       false        ->  throw("Error: sasl application not started."),
+                        error;
+       {sasl, _, _} ->  ok
+   end.
+
+ensure_mf_h_handler_used(Node) ->
+   %% is log_mf_h used ?
+   Handlers = rpc:block_call(Node, gen_event, which_handlers, [error_logger]),
+   case lists:any(fun(L)-> L == log_mf_h end, Handlers) of
+       false -> throw("Error: log_mf_h handler not used in sasl."),
+                error;
+       true  -> ok
+   end.
+
+ensure_rb_mode(Node, PrevLog) ->
+    ok = ensure_rb_module_loaded(Node),
+    ok = is_rb_compatible(Node),
+    ok = is_rb_server_running(Node, PrevLog),
+    ok.
+
+
+ensure_rb_module_loaded(Node) ->
+   %% Need to ensure that module is loaded in order to detect exported
+   %% functions on interactive nodes
+   case rpc:block_call(Node, code, ensure_loaded, [rb]) of
+       {badrpc, Reason} ->
+	   throw("Error: badrpc - " ++ io_lib:format("~tp",[Reason]));
+       {error, Reason} ->
+	   throw("Error: rb module load error - " ++ io_lib:format("~tp",[Reason]));
+       {module,rb} ->
+	   ok
+   end.
+
+is_rb_compatible(Node) ->
+   %% Simply test that rb:log_list/0 is exported
+   case rpc:block_call(Node, erlang, function_exported, [rb, log_list, 0]) of
+       false -> throw("Error: Node's Erlang release must be at least R16B02.");
+       true  -> ok
+   end.
+
+is_rb_server_running(Node, LogState) ->
+   %% If already started, somebody else may use it.
+   %% We can not use it too, as far log file would be overriden. Not fair.
+   case rpc:block_call(Node, erlang, whereis, [rb_server]) of
+       Pid when is_pid(Pid), (LogState == false) ->
+	   throw("Error: rb_server is already started and maybe used by someone.");
+       Pid when is_pid(Pid) ->
+	   ok;
+       undefined ->
+	   ok
+   end.
diff --git a/lib/observer/test/observer_SUITE.erl b/lib/observer/test/observer_SUITE.erl
index 5cf719acb1..c69fdf4bdf 100644
--- a/lib/observer/test/observer_SUITE.erl
+++ b/lib/observer/test/observer_SUITE.erl
@@ -22,6 +22,8 @@
 -include_lib("wx/include/wx.hrl").
 -include_lib("observer/src/observer_tv.hrl").
 
+-define(ID_LOGVIEW, 5).
+
 %% Test server specific exports
 -export([all/0, suite/0,groups/0]).
 -export([init_per_testcase/2, end_per_testcase/2,
@@ -44,8 +46,9 @@ all() ->
 
 groups() ->
     [{gui, [],
-      [basic
-      , process_win, table_win
+      [basic,
+       process_win,
+       table_win
       ]
      }].
 
@@ -107,7 +110,7 @@ appup_file(Config) when is_list(Config) ->
 basic(suite) -> [];
 basic(doc) -> [""];
 basic(Config) when is_list(Config) ->
-    timer:send_after(100, "foobar"), %% Otherwise the timer sever gets added to procs
+    timer:send_after(100, "foobar"), %% Otherwise the timer server gets added to procs
     ProcsBefore = processes(),
     NumProcsBefore = length(ProcsBefore),
 
@@ -126,7 +129,7 @@ basic(Config) when is_list(Config) ->
 		    timer:sleep(200),
 		    ok = wxNotebook:advanceSelection(Notebook)
 	    end,
-    %% Just verify that we can toogle trough all pages
+    %% Just verify that we can toggle through all pages
     [_|_] = [Check(N, false) || N <- lists:seq(1, Count)],
     %% Cause it to resize
     Frame = get_top_level_parent(Notebook),
@@ -214,10 +217,27 @@ test_page(Title, Window) ->
 process_win(suite) -> [];
 process_win(doc) -> [""];
 process_win(Config) when is_list(Config) ->
+    % Stop SASL if already started
+    SaslStart = case whereis(sasl_sup) of
+                  undefined -> false;
+                  _         -> application:stop(sasl),
+                               true
+                end,
+    % Define custom sasl and log_mf_h app vars
+    Privdir=?config(priv_dir,Config),
+    application:set_env(sasl, sasl_error_logger, tty),
+    application:set_env(sasl, error_logger_mf_dir, Privdir),
+    application:set_env(sasl, error_logger_mf_maxbytes, 1000),
+    application:set_env(sasl, error_logger_mf_maxfiles, 5),
+    application:start(sasl),
     ok = observer:start(),
     ObserverNB = setup_whitebox_testing(),
     Parent = get_top_level_parent(ObserverNB),
-    Frame = observer_procinfo:start(self(), Parent, self()),
+    % Activate log view
+    whereis(observer) ! #wx{id = ?ID_LOGVIEW, event = #wxCommand{type = command_menu_selected}},
+    timer:sleep(1000),
+    % Process window tests (use sasl_sup for a non empty Log tab)
+    Frame = observer_procinfo:start(whereis(sasl_sup), Parent, self()),
     PIPid = wx_object:get_pid(Frame),
     PIPid ! {get_debug_info, self()},
     Notebook = receive {procinfo_debug, NB} -> NB end,
@@ -229,6 +249,11 @@ process_win(Config) when is_list(Config) ->
     [_|_] = [Check(N) || N <- lists:seq(1, Count)],
     PIPid ! #wx{event=#wxClose{type=close_window}},
     observer:stop(),
+    application:stop(sasl),
+    case SaslStart of
+         true  -> application:start(sasl);
+         false -> ok
+    end,
     ok.
 
 table_win(suite) -> [];