Added skeleton for logging subsystem.
authorStanislaw Klekot <dozzie@jarowit.net>
Wed, 17 Sep 2014 17:04:37 +0000 (19:04 +0200)
committerStanislaw Klekot <dozzie@jarowit.net>
Wed, 17 Sep 2014 17:04:37 +0000 (19:04 +0200)
priv/haircut
priv/term2json [new file with mode: 0755]
src/haircut.app.src
src/haircut_file_term_h.erl [new file with mode: 0644]
src/haircut_log_activity.erl [new file with mode: 0644]
src/haircut_log_h.erl
src/haircut_log_operational.erl [new file with mode: 0644]
src/haircut_log_sup.erl [new file with mode: 0644]
src/haircut_sup.erl

index 3c59c61..c622577 100755 (executable)
@@ -78,7 +78,7 @@ setup_indira(Opts) ->
   % TODO: more control sockets?
   indira:add_listener(indira_unix, Opts#opts.control_socket),
   indira:set_commander(haircut_commander),
-  indira:setup_logging(haircut, [{stdout, color}]),
+  indira:setup_logging(haircut, [{gen_event, haircut_log_h, []}]),
   ok.
 
 %% }}}
diff --git a/priv/term2json b/priv/term2json
new file mode 100755 (executable)
index 0000000..49872e4
--- /dev/null
@@ -0,0 +1,33 @@
+#!/usr/bin/escript
+%%! +W w -pz ebin -env ERL_LIBS deps
+
+main(_) ->
+  read_print_loop(),
+  ok.
+
+read_print_loop() ->
+  case io:get_line("") of
+    eof ->
+      ok;
+    Data ->
+      Term = load_term(Data),
+      {ok, JSON} = indira_proto_serializer:encode(Term),
+      io:put_chars([JSON, "\n"]),
+      read_print_loop()
+  end.
+
+load_term(Data) when is_binary(Data) ->
+  load_term(binary_to_list(Data));
+
+load_term(Data) ->
+  Line = string:strip(Data),
+  case lists:last(Line) of
+    $. ->
+      {ok, Tokens, _LineNo} = erl_scan:string(Line);
+    _ ->
+      {ok, Tokens, _LineNo} = erl_scan:string(Line ++ ".")
+  end,
+  {ok, Term} = erl_parse:parse_term(Tokens),
+  Term.
+
+%% vim:ft=erlang
index 42d5373..68bcdc2 100644 (file)
@@ -1,7 +1,15 @@
 {application, haircut, [
   {description, "IRC bot"},
   {vsn, "0.0.1"}, % remember about `overview.edoc'
-  {registered, [haircut_sup, haircut_commander, haircut_bot, haircut_bot_sup]},
+  {registered, [
+    haircut_sup,
+    haircut_commander,
+    haircut_log_sup,
+    haircut_log_activity,
+    haircut_log_operational,
+    haircut_bot_sup,
+    haircut_bot
+  ]},
   {applications, [kernel, stdlib, ealirc]},
   {mod, {haircut_app, []}},
   {env, [
diff --git a/src/haircut_file_term_h.erl b/src/haircut_file_term_h.erl
new file mode 100644 (file)
index 0000000..86ff8f3
--- /dev/null
@@ -0,0 +1,98 @@
+%%%---------------------------------------------------------------------------
+%%% @doc
+%%%   Log handler for {@link error_logger} writing flat files with term
+%%%   formatting. This handler writes all events (without regard to whether it
+%%%   was `*_msg' or `*_report') to a file formatted as Erlang term.
+%%% @end
+%%%---------------------------------------------------------------------------
+
+-module(haircut_file_term_h).
+
+-behaviour(gen_event).
+
+%%% gen_event callbacks
+-export([init/1, terminate/2]).
+-export([handle_event/2, handle_call/2, handle_info/2]).
+-export([code_change/3]).
+
+%%%---------------------------------------------------------------------------
+%%% types
+
+-record(state, {file, fh}).
+
+%%%---------------------------------------------------------------------------
+%%% gen_event callbacks
+
+%%----------------------------------------------------------
+%% initialization and cleanup {{{
+
+%% @private
+%% @doc Initialize {@link gen_event} state.
+
+init(File) ->
+  FileABS = filename:absname(File),
+  case file:open(FileABS, [append, raw]) of
+    {ok, FH} ->
+      {ok, #state{file = FileABS, fh = FH}};
+    {error, Reason} ->
+      {error, Reason}
+  end.
+
+%% @private
+%% @doc Clean up {@link gen_event} state.
+
+terminate(_Reason, _State = #state{fh = FH}) ->
+  file:close(FH).
+
+%% }}}
+%%----------------------------------------------------------
+%% communication {{{
+
+%% @private
+%% @doc Handle {@link gen_event:notify/2}.
+
+handle_event(Event, State = #state{fh = FH}) ->
+  {MS,S,US} = now(),
+  Time = io_lib:format("~B.~6..0B", [MS * 1000000 + S,US]),
+  EventLine = format_event(Event),
+  file:write(FH, [Time, "\t", EventLine, "\n"]),
+  {ok, State}.
+
+format_event({Level, Data} = _Event) when is_atom(Level) ->
+  % 2G columns should be \infty, term should fit in this width
+  [atom_to_list(Level), "\t", io_lib:print(Data, 1, 16#ffffffff, -1)];
+format_event(Event) ->
+  format_event({unknown, Event}).
+
+%% @private
+%% @doc Handle {@link gen_event:call/3}.
+
+handle_call(reopen = _Request, State = #state{file = File, fh = FH}) ->
+  file:close(FH), % remember to close the old handle before possibly dying
+  {ok, NewFH} = file:open(File, [append, raw]), % die on any problem
+  {ok, ok, State#state{fh = NewFH}};
+
+handle_call(_Request, State) ->
+  {ok, {error, unknown}, State}.
+
+%% @private
+%% @doc Handle incoming messages.
+
+handle_info(_Msg, State) ->
+  {ok, State}.
+
+%% }}}
+%%----------------------------------------------------------
+%% code change {{{
+
+%% @private
+%% @doc Handle code change.
+
+code_change(_OldVsn, State, _Extra) ->
+  {ok, State}.
+
+%% }}}
+%%----------------------------------------------------------
+
+%%%---------------------------------------------------------------------------
+%%% vim:ft=erlang:foldmethod=marker
diff --git a/src/haircut_log_activity.erl b/src/haircut_log_activity.erl
new file mode 100644 (file)
index 0000000..55b6323
--- /dev/null
@@ -0,0 +1,27 @@
+%%%---------------------------------------------------------------------------
+%%% @doc
+%%%   Logger for activity (talks, presence and issued !commands).
+%%% @end
+%%%---------------------------------------------------------------------------
+
+-module(haircut_log_activity).
+
+%%% public API
+-export([start_link/0]).
+
+%%%---------------------------------------------------------------------------
+%%% public API
+
+start_link() ->
+  % TODO: unhardcode this
+  File = "run/activity.log",
+  case gen_event:start_link({local, ?MODULE}) of
+    {ok, Pid} ->
+      gen_event:add_handler(Pid, haircut_file_term_h, File),
+      {ok, Pid};
+    {error, Reason} ->
+      {error, Reason}
+  end.
+
+%%%---------------------------------------------------------------------------
+%%% vim:ft=erlang:foldmethod=marker
index cefd3b5..00e2fd2 100644 (file)
@@ -5,6 +5,8 @@
 %%%   formatted and stored and what log types are to be handled by Indira.
 %%%
 %%% @TODO Send events with stack trace somewhere to log detailed details.
+%%% @TODO Split this module to collect operational logs separately from usage
+%%%   (operational logs will go to Indira in the future).
 %%% @end
 %%%---------------------------------------------------------------------------
 
@@ -61,7 +63,7 @@ handle_event({info_report, _GLead, {_Pid, Type, Report}} = _Event, State) ->
   case {Type,Report} of
     {progress, [{application, App}, {started_at, _AppNode}]} ->
       % application started
-      io:fwrite(". application ~s started~n", [App]);
+      oplog(info, "application started", [{application, App}]);
     {progress, [{supervisor, {_SupPid, _SupName}}, {started, _Child}]} ->
       % child started
       % TODO: what is `SupName' when supervisor is not a registered process?
@@ -69,16 +71,18 @@ handle_event({info_report, _GLead, {_Pid, Type, Report}} = _Event, State) ->
       ignore;
     {std_info, [{application, App}, {exited, stopped}, {type, _StartType}]} ->
       % application stopped
-      io:fwrite(". application ~s stopped~n", [App]);
+      oplog(info, "application stopped", [{application, App}]);
     {std_info, [{application, App}, {exited, Reason}, {type, _StartType}]} ->
       % application stopped unexpectedly
-      io:fwrite("!! application ~s crashed (~1024p)~n", [App, Reason]);
+      oplog(error, "application crashed",
+            [{application, App}, {reason, normalize_reason(Reason)}]);
     {std_info, [{indira_info, MsgType} | Context]} ->
       % Indira INFO messages
-      io:fwrite(". indira[~p]: ~1024p~n", [MsgType, Context]);
+      oplog(info, MsgType, [{context, Context}]);
     {_,_} ->
       % TODO: haircut's own logs
       % TODO: warnings (+W i)
+      io:fwrite("# ignored info type=~p: ~1024p~n", [Type, Report]),
       ignore
   end,
   {ok, State};
@@ -94,20 +98,31 @@ handle_event({error_report, _GLead, {Pid, Type, Report}} = _Event, State) ->
     {supervisor_report, [{supervisor, {_SupPid, _SupName} = SupId},
                           {errorContext, start_error},
                           {reason, Reason}, {offender, ChildProps}]} ->
-      % similar to crash report above, but cleaner MFA specification and is
-      % generated even for processes that got exit signal
-      format_supervisor_start_error_report({SupId, Pid}, Reason, ChildProps);
+      oplog(error, "process start error",
+            [{reason, normalize_reason(Reason)},
+              {supervisor, supervisor_info(Pid, SupId)},
+              {child, child_info(ChildProps)}]);
     {supervisor_report, [{supervisor, {_SupPid, _SupName} = SupId},
                           {errorContext, child_terminated},
                           {reason, Reason}, {offender, ChildProps}]} ->
       % similar to crash report above, but cleaner MFA specification and is
       % generated even for processes that got exit signal
-      format_supervisor_crash_report({SupId, Pid}, Reason, ChildProps);
+      TrueReason = normalize_reason(Reason),
+      {Level, Message} = case TrueReason of
+        normal   -> {info,  "process stopped"};
+        shutdown -> {info,  "process shut down"};
+        _        -> {error, "process crashed"}
+      end,
+      oplog(Level, Message,
+            [{reason, TrueReason},
+              {supervisor, supervisor_info(Pid, SupId)},
+              {child, child_info(ChildProps)}]);
     {std_error, [{indira_error, MsgType} | Context]} ->
-      io:fwrite("!! indira[~p]: ~1024p~n", [MsgType, Context]);
+      oplog(critical, MsgType, [{context, Context}]);
     {_,_} ->
       % TODO: haircut's own logs
       % TODO: warnings (no +W flag)
+      io:fwrite("# ignored error type=~p: ~1024p~n", [Type, Report]),
       ignore
   end,
   {ok, State};
@@ -116,8 +131,9 @@ handle_event({error_report, _GLead, {Pid, Type, Report}} = _Event, State) ->
 handle_event({warning_report, _GLead, {_Pid, Type, Report}} = _Event, State) ->
   case {Type,Report} of
     {std_warning, [{indira_error, MsgType} | Context]} ->
-      io:fwrite("! indira[~p]: ~1024p~n", [MsgType, Context]);
+      oplog(error, MsgType, [{context, Context}]);
     {_,_} ->
+      io:fwrite("# ignored warning type=~p: ~1024p~n", [Type, Report]),
       ignore
   end,
   {ok, State};
@@ -152,113 +168,97 @@ code_change(_OldVsn, State, _Extra) ->
 %%----------------------------------------------------------
 
 %%%---------------------------------------------------------------------------
+
+%% @doc Send operational log.
+%%
+%% @spec oplog(atom(), atom() | string() | binary(), list()) ->
+%%   atom()
+
+oplog(Level, Event, Context) when is_list(Event) ->
+  oplog(Level, list_to_binary(Event), Context);
+
+oplog(Level, Event, Context) when is_binary(Event); is_atom(Event) ->
+  try
+    Message = {Level, [{event, Event} | Context]},
+    gen_event:notify(haircut_log_operational, Message)
+  catch
+    error:badarg -> ignore
+  end.
+
+%%%---------------------------------------------------------------------------
 %%% helper functions {{{
 
+supervisor_info(Pid, {local, SupName} = _SupId) ->
+  Info = [
+    {name, SupName},
+    {message_origin, pid_to_binary(Pid)}
+  ],
+  Info;
+
+supervisor_info(Pid, {SupPid, SupName} = _SupId) when is_pid(SupPid) ->
+  Info = [
+    {pid, pid_to_binary(SupPid)},
+    {name, SupName},
+    {message_origin, pid_to_binary(Pid)}
+  ],
+  Info.
+
 %%----------------------------------------------------------
 
-format_supervisor_crash_report(Supervisor, shutdown = _Reason, ChildProps) ->
-  % child was ordered to stop
-  Pid = proplists:get_value(pid, ChildProps),
-  Name = proplists:get_value(name, ChildProps),
-  ChildType = proplists:get_value(child_type, ChildProps),
-  case {Name,ChildType} of
-    {undefined, _} ->
-      % simple_one_for_one, swarm worker (swarm supervisor? unlikely)
-      io:fwrite("! swarm ~p (~p under ~1024p) shut down~n",
-                [Pid, ChildType, format_supervisor(Supervisor)]);
-    {_, supervisor} ->
-      io:fwrite("! supervisor ~p (pid ~p) shut down~n", [Name, Pid]);
-    {_, worker} ->
-      io:fwrite("! ~p (pid ~p) shut down~n", [Name, Pid])
-  end,
-  ok;
-
-format_supervisor_crash_report(Supervisor, normal = _Reason, ChildProps) ->
-  % child stopped
-  Pid = proplists:get_value(pid, ChildProps),
-  Name = proplists:get_value(name, ChildProps),
-  ChildType = proplists:get_value(child_type, ChildProps),
-  case {Name,ChildType} of
-    {undefined, _} ->
-      % simple_one_for_one, swarm worker (swarm supervisor? unlikely)
-      io:fwrite(". swarm ~p (~p under ~1024p) stopped normally~n",
-                [Pid, ChildType, format_supervisor(Supervisor)]);
-    {_, supervisor} ->
-      io:fwrite(". supervisor ~p (pid ~p) stopped normally~n", [Name, Pid]);
-    {_, worker} ->
-      io:fwrite(". ~p (pid ~p) stopped normally~n", [Name, Pid])
-  end,
-  ok;
-
-format_supervisor_crash_report(Supervisor, Reason, ChildProps) ->
-  % child died
-  Pid = proplists:get_value(pid, ChildProps),
-  Name = proplists:get_value(name, ChildProps),
-  ChildType = proplists:get_value(child_type, ChildProps),
-  TrueReason = format_exit_reason(Reason),
-  case {Name,ChildType} of
-    {undefined, _} ->
-      % simple_one_for_one, swarm worker (swarm supervisor? unlikely)
-      io:fwrite("! swarm ~p (~p under ~1024p) crashed: ~1024p~n",
-                [Pid, ChildType, format_supervisor(Supervisor), TrueReason]);
-    {_, supervisor} ->
-      io:fwrite("! supervisor ~p (pid ~p) crashed: ~1024p~n",
-                [Name, Pid, TrueReason]);
-    {_, worker} ->
-      io:fwrite("! ~p (pid ~p) crashed: ~1024p~n", [Name, Pid, TrueReason])
-  end,
-  ok.
+child_info(ChildProps) ->
+  collect_child_info(ChildProps).
 
 %%----------------------------------------------------------
 
-format_supervisor_start_error_report(Supervisor, Reason, ChildProps) ->
-  Name = proplists:get_value(name, ChildProps),
-  ChildType = proplists:get_value(child_type, ChildProps),
-  TrueReason = format_exit_reason(Reason),
-  case {Name,ChildType} of
-    {undefined, _} ->
-      % simple_one_for_one, swarm worker (swarm supervisor? unlikely)
-      io:fwrite("! swarm ~p (under ~1024p) didn't start: ~1024p~n",
-                [ChildType, format_supervisor(Supervisor), TrueReason]);
-    {_, supervisor} ->
-      io:fwrite("! supervisor ~p didn't start: ~p~n",
-                [Name, TrueReason]);
-    {_, worker} ->
-      io:fwrite("! ~p didn't start: ~p~n", [Name, TrueReason])
-  end,
-  ok.
+collect_child_info([] = _ChildProps) ->
+  [];
 
-%%----------------------------------------------------------
+collect_child_info([{pid, undefined} | RestInfo]) ->
+  [{pid, undefined} | collect_child_info(RestInfo)];
+collect_child_info([{pid, Pid} | RestInfo]) when is_pid(Pid) ->
+  [{pid, pid_to_binary(Pid)} | collect_child_info(RestInfo)];
+
+collect_child_info([{name, undefined} | RestInfo]) ->
+  collect_child_info(RestInfo);
+collect_child_info([{name, Name} | RestInfo]) ->
+  [{name, Name} | collect_child_info(RestInfo)];
 
-format_supervisor({{local, Name}, _Pid} = _Supervisor) ->
-  Name;
+collect_child_info([{child_type, Type} | RestInfo]) ->
+  [{type, Type} | collect_child_info(RestInfo)];
 
-format_supervisor({{Pid, Name}, Pid} = _Supervisor) ->
-  {Name, Pid};
+collect_child_info([_Info | RestInfo]) ->
+  collect_child_info(RestInfo).
+
+%%----------------------------------------------------------
 
-format_supervisor({{_SomePid, Name}, Pid} = _Supervisor) ->
-  {Name, Pid}.
+pid_to_binary(Pid) when is_pid(Pid) ->
+  list_to_binary(pid_to_list(Pid)).
 
 %%----------------------------------------------------------
 
-format_exit_reason({{TrueReason, _Value}, Stack} = _Reason)
+normalize_reason({{TrueReason, _Value}, Stack} = _Reason)
 when is_list(Stack) ->
   % `{badmatch,V}', `{case_clause,V}', `{try_clause,V}', ...
   TrueReason;
 
-format_exit_reason({undef, [{MissM,MissF,MissArgs} | _] = _Stack} = _Reason) ->
+normalize_reason({undef, [{MissM,MissF,MissArgs} | _] = _Stack} = _Reason) ->
   % undefined function
+  % TODO: FuncName = <<
+  %   (atom_to_binary(MissM, utf8))/binary, ":",
+  %   (atom_to_binary(MissF, utf8))/binary, "/",
+  %   (list_to_binary(integer_to_list(length(MissArgs))))/binary
+  % >>
   {undef, {MissM, MissF, length(MissArgs)}};
 
-format_exit_reason({TrueReason, Stack} = _Reason) when is_list(Stack) ->
+normalize_reason({TrueReason, Stack} = _Reason) when is_list(Stack) ->
   % process died (with stack trace)
   TrueReason;
 
-format_exit_reason({'EXIT', TrueReason} = _Reason) ->
+normalize_reason({'EXIT', TrueReason} = _Reason) ->
   % `catch(exit(...))'
   TrueReason;
 
-format_exit_reason(Reason) ->
+normalize_reason(Reason) ->
   Reason.
 
 %%----------------------------------------------------------
diff --git a/src/haircut_log_operational.erl b/src/haircut_log_operational.erl
new file mode 100644 (file)
index 0000000..68493f6
--- /dev/null
@@ -0,0 +1,27 @@
+%%%---------------------------------------------------------------------------
+%%% @doc
+%%%   Logger for operational events.
+%%% @end
+%%%---------------------------------------------------------------------------
+
+-module(haircut_log_operational).
+
+%%% public API
+-export([start_link/0]).
+
+%%%---------------------------------------------------------------------------
+%%% public API
+
+start_link() ->
+  % TODO: unhardcode this
+  File = "run/operational.log",
+  case gen_event:start_link({local, ?MODULE}) of
+    {ok, Pid} ->
+      gen_event:add_handler(Pid, haircut_file_term_h, File),
+      {ok, Pid};
+    {error, Reason} ->
+      {error, Reason}
+  end.
+
+%%%---------------------------------------------------------------------------
+%%% vim:ft=erlang:foldmethod=marker
diff --git a/src/haircut_log_sup.erl b/src/haircut_log_sup.erl
new file mode 100644 (file)
index 0000000..03e4d41
--- /dev/null
@@ -0,0 +1,42 @@
+%%%---------------------------------------------------------------------------
+%%% @doc
+%%%   Logger supervisor.
+%%% @end
+%%%---------------------------------------------------------------------------
+
+-module(haircut_log_sup).
+
+-behaviour(supervisor).
+
+%%% public API
+-export([start_link/0]).
+
+%%% supervisor callbacks
+-export([init/1]).
+
+%%%---------------------------------------------------------------------------
+%%% public API
+
+start_link() ->
+  supervisor:start_link({local, ?MODULE}, ?MODULE, []).
+
+%%%---------------------------------------------------------------------------
+%%% supervisor callbacks
+
+init([] = _Args) ->
+  % TODO: haircut_log_syslog, but some time later it will get moved to Indira
+  Children = [
+    {haircut_log_activity,
+      {haircut_log_activity, start_link, []},
+      permanent, 5000, worker, dynamic},
+    {haircut_log_operational,
+      {haircut_log_operational, start_link, []},
+      permanent, 5000, worker, dynamic}
+  ],
+  {ok, {
+    {one_for_one, 5, 10},
+    Children
+  }}.
+
+%%%---------------------------------------------------------------------------
+%%% vim:ft=erlang:foldmethod=marker
index 8c740f1..8b7f224 100644 (file)
@@ -25,6 +25,9 @@ start_link() ->
 
 init([] = _Args) ->
   Children = [
+    {haircut_log_sup,
+      {haircut_log_sup, start_link, []},
+      permanent, 5000, supervisor, [haircut_log_sup]},
     {haircut_commander,
       {haircut_commander, start_link, []},
       permanent, 5000, worker, [haircut_commander]},