eLog/src/eRum.erl

-module(eRum).


-include("rumDef.hrl").
-include("rumCom.hrl").

-compile(inline).
-compile({inline_size, 150}).

%% API
-export([
   %% start stop
   start/0
   , stop/0

   %% log and log param
   , dispatchLog/12
   , doLogImpl/13
   , safeFormat/3
   , unsafeFormat/2
   , getMd/0
   , setMd/1
   , getLogLevel/1
   , getLogLevel/2
   , setLogLevel/2
   , setLogLevel/3
   , setLogLevel/4
   , getLogLevels/1
   , upLogLevelCfg/1
   , setLogHwm/2
   , setLogHwm/3
   , setLogHwm/4
   , rotateHandler/1
   , rotateHandler/2
   , rotateSink/1
   , rotateAll/0

   %% stack parse
   , parseStack/1
   , parseStack/3

   %% trace
   , trace/2
   , trace/3
   , traceFile/2
   , trace_file/3
   , trace_file/4
   , trace_console/1
   , trace_console/2
   , install_trace/2
   , install_trace/3
   , remove_trace/1
   , trace_state/3
   , trace_func/3
   , list_all_sinks/0
   , clear_all_traces/0
   , clear_trace_by_destination/1
   , stop_trace/1
   , stop_trace/3
   , status/0
]).

-record(trace_func_state_v1, {
   pid :: undefined | pid(),
   level :: rumAtomLevel(),
   count :: infinity | pos_integer(),
   format_string :: string(),
   timeout :: infinity | pos_integer(),
   started = os:timestamp() :: erlang:timestamp() %% use os:timestamp for compatability
}).

start() ->
   application:ensure_all_started(eRum).

stop() ->
   application:stop(eRum).

-spec dispatchLog(atom(), rumAtomLevel(), pid(), node(), atom(), atom(), integer(), list(), string(), list() | none, pos_integer(), safe | unsafe) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}.
%% this is the same check that the parse transform bakes into the module at compile time see rumTransform (lines 173-216)
dispatchLog(Sink, Severity, Pid, Node, Module, Function, Line, Metadata, Format, Args, Size, Safety) ->
   case ?eRumCfg:get(Sink) band Severity /= 0 of
      true ->
         doLogImpl(Severity, Pid, Node, Module, Function, Line, Metadata, Format, Args, Severity, Size, Sink, Safety);
      _ ->
         ok
   end.

doLogImpl(Severity, Pid, Node, Module, Function, Line, Metadata, Format, Args, Severity, Size, Sink, Safety) ->
   TraceFilters = rumConfig:ptGet({Sink, trace}, []),
   Destinations = ?IIF(TraceFilters /= [], rumUtil:check_traces(Metadata, Severity, TraceFilters, []), []),

   MsgStr = ?IIF(Args /= [] andalso Args /= undefined, ?IIF(Safety == safe, safeFormat(Format, [Args], [{charsLimit, Size}]), unsafeFormat(Format, [Args])), Format),
   NowMs = rumTime:nowMs(),
   NowStr = rumUtil:msToBinStr(NowMs),
   RumMsg = #rumMsg{severity = Severity, pid = Pid, node = Node, module = Module, function = Function, line = Line, metadata = Metadata, datetime = NowStr, timestamp = NowMs, message = MsgStr, destinations = Destinations},

   case rumConfig:ptGet({Sink, async}, false) of
      true ->
         gen_emm:info_notify(Sink, {mWriteLog, RumMsg});
      false ->
         gen_emm:call_notify(Sink, {mWriteLog, RumMsg})
   end,
   case whereis(?RumTrackSink) of
      undefined ->
         ok;
      TraceSinkPid ->
         gen_emm:info_notify(TraceSinkPid, {mWriteLog, RumMsg})
   end.

%% @doc Get lager metadata for current process
-spec getMd() -> [{atom(), any()}].
getMd() ->
   case erlang:get(?PdMdKey) of
      undefined -> [];
      MD -> MD
   end.

%% @doc Set lager metadata for current process.
%% Will badarg if you don't supply a list of {key, value} tuples keyed by atoms.
-spec setMd([{atom(), any()}, ...]) -> ok.
setMd(NewMD) when is_list(NewMD) ->
   %% make sure its actually a real proplist
   case lists:all(
      fun({Key, _Value}) when is_atom(Key) -> true;
         (_) -> false
      end, NewMD) of
      true ->
         erlang:put(?PdMdKey, NewMD),
         ok;
      _ ->
         erlang:error(badarg)
   end;
setMd(_) ->
   erlang:error(badarg).

%% @doc Set the loglevel for a particular backend.
setLogLevel(Handler, Level) when is_atom(Level) ->
   setLogLevel(?RumDefSink, Handler, undefined, Level).

%% @doc Set the loglevel for a particular backend that has multiple identifiers
%% (eg. the file backend).
setLogLevel(Handler, Ident, Level) when is_atom(Level) ->
   setLogLevel(?RumDefSink, Handler, Ident, Level).

%% @doc Set the loglevel for a particular sink's backend that potentially has
%% multiple identifiers. (Use `undefined' if it doesn't have any.)
setLogLevel(Sink, Handler, Ident, Level) when is_atom(Level) ->
   HandlerArg =
      case Ident of
         undefined -> Handler;
         _ -> {Handler, Ident}
      end,
   Reply = gen_emm:call(Sink, HandlerArg, {mSetLogLevel, Level}, infinity),
   upLogLevelCfg(Sink),
   Reply.


%% @doc Get the loglevel for a particular backend on the default sink. In the case that the backend has multiple identifiers, the lowest is returned.
getLogLevel(Handler) ->
   getLogLevel(?RumDefSink, Handler).

%% @doc Get the loglevel for a particular sink's backend. In the case that the backend
%% has multiple identifiers, the lowest is returned.
getLogLevel(Sink, Handler) ->
   case gen_emm:call(Sink, Handler, mGetLogLevel, infinity) of
      Mask when is_integer(Mask) ->
         case rumUtil:maskToLevels(Mask) of
            [] -> none;
            Levels -> hd(Levels)
         end;
      Y -> Y
   end.

getLogLevels(Sink) ->
   [gen_emm:call(Sink, Handler, mGetLogLevel, infinity) || Handler <- gen_emm:which_epm(Sink)].

%% @doc Set the loghwm for the default sink.
setLogHwm(Handler, Hwm) when is_integer(Hwm) ->
   setLogHwm(?RumDefSink, Handler, Hwm).

%% @doc Set the loghwm for a particular backend.
setLogHwm(Sink, Handler, Hwm) when is_integer(Hwm) ->
   gen_emm:call(Sink, Handler, {mSetLogHwm, Hwm}, infinity).

%% @doc Set the loghwm (log high water mark) for file backends with multiple identifiers
setLogHwm(Sink, Handler, Ident, Hwm) when is_integer(Hwm) ->
   gen_emm:call(Sink, {Handler, Ident}, {mSetLogHwm, Hwm}, infinity).

%% @doc recalculate min log level
upLogLevelCfg(error_logger) ->
   %% Not a sink under our control, part of the Erlang logging
   %% utility that error_logger_lager_h attaches to
   true;
upLogLevelCfg(Sink) ->
   Traces = rumConfig:ptGet({Sink, trace}, []),
   AllLogLevel = allLogLevel(getLogLevels(Sink), 0),
   case Traces /= [] of
      true ->
         ets:insert(?eRumEts, {Sink, 16#ff}),
         AllSinks = ets:tab2list(?eRumEts),
         rumKvsToBeam:load(?eRumCfg, AllSinks);
      _ ->
         ets:insert(?eRumEts, {Sink, AllLogLevel}),
         AllSinks = ets:tab2list(?eRumEts),
         rumKvsToBeam:load(?eRumCfg, AllSinks)
   end.

allLogLevel([], Acc) ->
   Acc;
allLogLevel([OneLv | Levels], Acc) ->
   allLogLevel(Levels, OneLv bor Acc).

rotateSink(Sink) ->
   Handlers = rumConfig:ptGet(handlers, []),
   RotateHandlers = lists:filtermap(
      fun({Handler, _, S}) when S == Sink -> {true, {Handler, Sink}};
         (_) -> false
      end,
      Handlers),
   rotateHandlers(RotateHandlers).

rotateAll() ->
   rotateHandlers(lists:map(fun({H, _, S}) -> {H, S} end,
      rumConfig:ptGet(handlers, []))).


rotateHandlers(Handlers) ->
   [rotateHandler(Handler, Sink) || {Handler, Sink} <- Handlers].


rotateHandler(Handler) ->
   Handlers = rumConfig:ptGet(handlers, []),
   case lists:keyfind(Handler, 1, Handlers) of
      {Handler, _, Sink} -> rotateHandler(Handler, Sink);
      false -> ok
   end.

rotateHandler(Handler, Sink) ->
   gen_emm:call(Sink, Handler, mRotate, ?RumRotateTimeout).

%% @doc Print stacktrace in human readable form
parseStack(Stacktrace) ->
   <<
      begin
         case Location of
            [] ->
               <<"     ", (atom_to_binary(Mod, utf8))/binary, ":", (atom_to_binary(Func, utf8))/binary, "(", (eFmt:formatBin("~w", [Arity]))/binary, ")\n">>;
            [{file, File}, {line, Line}] ->
               <<"     ", (atom_to_binary(Mod, utf8))/binary, ":", (atom_to_binary(Func, utf8))/binary, "/", (integer_to_binary(Arity))/binary, "(", (unicode:characters_to_binary(File))/binary, ":", (integer_to_binary(Line))/binary, ")\n">>;
            _ ->
               <<"     ", (atom_to_binary(Mod, utf8))/binary, ":", (atom_to_binary(Func, utf8))/binary, "(", (eFmt:formatBin("~w", [Arity]))/binary, ")", (eFmt:formatBin("~w", [Location]))/binary, "\n">>
         end
      end || {Mod, Func, Arity, Location} <- Stacktrace
   >>.

parseStack(Class, Reason, Stacktrace) ->
   eFmt:formatBin(<<"~n  Class:~s~n  Reason:~p~n  Stacktrace:~s">>, [Class, Reason, parseStack(Stacktrace)]).

trace(BkdMod, Filter) ->
   trace(BkdMod, Filter, debug).

trace({rumBkdFile, File}, Filter, Level) ->
   trace_file(File, Filter, Level);
trace(Backend, Filter, Level) ->
   case validateTraceFilters(Filter, Level, Backend) of
      {Sink, {ok, Trace}} ->
         add_trace_to_loglevel_config(Trace, Sink),
         {ok, {Backend, Filter, Level}};
      {_Sink, Error} ->
         Error
   end.

traceFile(File, Filter) ->
   trace_file(File, Filter, debug, []).

trace_file(File, Filter, Level) when is_atom(Level) ->
   trace_file(File, Filter, Level, []);

trace_file(File, Filter, Options) when is_list(Options) ->
   trace_file(File, Filter, debug, Options).

trace_file(File, Filter, Level, Options) ->
   FileName = rumUtil:parsePath(File),
   case validateTraceFilters(Filter, Level, {rumBkdFile, FileName}) of
      {Sink, {ok, Trace}} ->
         Handlers = rumConfig:ptGet(handlers, []),
         %% check if this file backend is already installed
         Res =
            case rumUtil:find_file(FileName, Handlers) of
               false ->
                  %% install the handler
                  LogFileConfig =
                     lists:keystore(level, 1,
                        lists:keystore(file, 1,
                           Options,
                           {file, FileName}),
                        {level, none}),
                  HandlerInfo =
                     eRum_app:startHandler(Sink, {rumBkdFile, FileName}, LogFileConfig),
                  rumConfig:ptSet(handlers, [HandlerInfo | Handlers]),
                  {ok, installed};
               {_Watcher, _Handler, Sink} ->
                  {ok, exists};
               {_Watcher, _Handler, _OtherSink} ->
                  {error, file_in_use}
            end,
         case Res of
            {ok, _} ->
               add_trace_to_loglevel_config(Trace, Sink),
               {ok, {{rumBkdFile, FileName}, Filter, Level}};
            {error, _} = E ->
               E
         end;
      {_Sink, Error} ->
         Error
   end.

trace_console(Filter) ->
   trace_console(Filter, debug).

trace_console(Filter, Level) ->
   trace(rumBkdConsole, Filter, Level).

stop_trace(Backend, Filter, Level) ->
   case validateTraceFilters(Filter, Level, Backend) of
      {Sink, {ok, Trace}} ->
         stop_trace_int(Trace, Sink);
      {_Sink, Error} ->
         Error
   end.

stop_trace({Backend, Filter, Level}) ->
   stop_trace(Backend, Filter, Level).


validateTraceFilters(Filters, Level, Backend) ->
   Sink = proplists:get_value(sink, Filters, ?RumDefSink),
   {Sink,
      rumUtil:validate_trace({
         proplists:delete(sink, Filters),
         Level,
         Backend
      })
   }.

%% Important: validate_trace_filters orders the arguments of
%% trace tuples differently than the way outside callers have
%% the trace tuple.
%%
%% That is to say, outside they are represented as 
%% `{Backend, Filter, Level}'
%%
%% and when they come back from validation, they're
%% `{Filter, Level, Backend}'
stop_trace_int({_Filter, _Level, Backend} = Trace, Sink) ->
   Traces = rumConfig:ptGet({Sink, trace}, []),
   NewTraces = lists:delete(Trace, Traces),
   _ = rumUtil:trace_filter([element(1, T) || T <- NewTraces]),
   %MinLevel = minimum_loglevel(get_loglevels() ++ get_trace_levels(NewTraces)),
   rumConfig:ptSet({Sink, trace}, NewTraces),
   eRum:upLogLevelCfg(Sink),

   case getLogLevel(Sink, Backend) of
      none ->
         %% check no other traces point here
         case lists:keyfind(Backend, 3, NewTraces) of
            false ->
               gen_emm:delEpm(Sink, Backend, []),
               rumConfig:ptSet(handlers,
                  lists:keydelete(Backend, 1,
                     rumConfig:ptGet(handlers, [])));
            _ ->
               ok
         end;
      _ ->
         ok
   end,
   ok.

%% @doc installs a lager trace handler into the target process (using sys:install) at the specified level.
-spec install_trace(pid(), rumAtomLevel()) -> ok.
install_trace(Pid, Level) ->
   install_trace(Pid, Level, []).

-spec install_trace(pid(), rumAtomLevel(), [{count, infinity | pos_integer()} | {format_string, string()} | {timeout, timeout()}]) -> ok.
install_trace(Pid, Level, Options) ->
   sys:install(Pid, {fun ?MODULE:trace_func/3, trace_state(Pid, Level, Options)}).

%% @doc remove a previously installed lager trace handler from the target process.
-spec remove_trace(pid()) -> ok.
remove_trace(Pid) ->
   sys:remove(Pid, fun ?MODULE:trace_func/3).

list_all_sinks() ->
   sets:to_list(
      lists:foldl(fun({_Watcher, _Handler, Sink}, Set) ->
         sets:add_element(Sink, Set)
                  end,
         sets:new(),
         rumConfig:ptGet(handlers, []))).

clear_traces_by_sink(Sinks) ->
   lists:foreach(
      fun(S) ->
         rumConfig:ptSet({S, trace}, []),
         eRum:upLogLevelCfg(S)
      end,
      Sinks).


clear_trace_by_destination(ID) ->
   Sinks = lists:sort(list_all_sinks()),
   Traces = find_traces(Sinks),
   [stop_trace_int({Filter, Level, Destination}, Sink) || {Sink, {Filter, Level, Destination}} <- Traces, Destination == ID].


clear_all_traces() ->
   Handlers = rumConfig:ptGet(handlers, []),
   clear_traces_by_sink(list_all_sinks()),
   _ = rumUtil:trace_filter(none),
   rumConfig:ptSet(handlers,
      lists:filter(
         fun({Handler, _Watcher, Sink}) ->
            case getLogLevel(Sink, Handler) of
               none ->
                  gen_emm:delEpm(Sink, Handler, []),
                  false;
               _ ->
                  true
            end
         end, Handlers)).

find_traces(Sinks) ->
   lists:foldl(fun(S, Acc) ->
      Traces = rumConfig:ptGet({S, trace}, []),
      Acc ++ lists:map(fun(T) -> {S, T} end, Traces)
               end,
      [],
      Sinks).

status() ->
   Handlers = rumConfig:ptGet(handlers, []),
   Sinks = lists:sort(list_all_sinks()),
   Traces = find_traces(Sinks),
   TraceCount = case length(Traces) of
                   0 -> 1;
                   N -> N
                end,
   Status = ["Lager status:\n",
      [begin
          Level = getLogLevel(Sink, Handler),
          get_sink_handler_status(Sink, Handler, Level)
       end || {Handler, _Watcher, Sink} <- lists:sort(fun({_, _, S1},
         {_, _, S2}) -> S1 =< S2 end,
         Handlers)],
      "Active Traces:\n",
      [begin
          LevelName =
             case rumUtil:maskToLevels(Level) of
                [] -> none;
                Levels -> hd(Levels)
             end,

          io_lib:format("Tracing messages matching ~p (sink ~s) at level ~p to ~p\n",
             [Filter, Sink, LevelName, Destination])
       end || {Sink, {Filter, Level, Destination}} <- Traces],
      [
         "Tracing Reductions:\n",
         case ?RumDefTracer:info('query') of
            {null, false} -> "";
            Query -> io_lib:format("~p~n", [Query])
         end
      ],
      [
         "Tracing Statistics:\n ",
         [begin
             [" ", atom_to_list(Table), ": ",
                integer_to_list(?RumDefTracer:info(Table) div TraceCount),
                "\n"]
          end || Table <- [input, output, filter]]
      ]],
   io:put_chars(Status).

get_sink_handler_status(Sink, Handler, Level) ->
   case Handler of
      {rumBkdFile, File} ->
         io_lib:format("File ~ts (~s) at level ~p\n", [File, Sink, Level]);
      rumBkdConsole ->
         io_lib:format("Console (~s) at level ~p\n", [Sink, Level]);
      _ ->
         []
   end.

%% @private
add_trace_to_loglevel_config(Trace, Sink) ->
   Traces = rumConfig:ptGet({Sink, trace}, []),
   case lists:member(Trace, Traces) of
      false ->
         NewTraces = [Trace | Traces],
         _ = rumUtil:trace_filter([element(1, T) || T <- NewTraces]),
         rumConfig:ptSet({Sink, trace}, [Trace | Traces]),
         eRum:upLogLevelCfg(Sink);
      _ ->
         ok
   end.

%% @doc Print the format string `Fmt' with `Args' safely with a size
%% limit of `Limit'. If the format string is invalid, or not enough
%% arguments are supplied 'FORMAT ERROR' is printed with the offending
%% arguments. The caller is NOT crashed.

unsafeFormat(Fmt, Args) ->
   try io_lib:format(Fmt, Args)
   catch
      _:_ -> io_lib:format("FORMAT ERROR: ~p ~p", [Fmt, Args])
   end.

safeFormat(Fmt, Args, Limit) ->
   try eFmt:formatBin(Fmt, Args, [{charsLimit, Limit}])
   catch
      _:_ -> eFmt:formatBin(<<"FORMAT ERROR: ~p ~p">>, [Fmt, Args], [{charsLimit, Limit}])
   end.

%% @private Print the format string `Fmt' with `Args' without a size limit.
%% This is unsafe because the output of this function is unbounded.
%%
%% Log messages with unbounded size will kill your application dead as
%% OTP mechanisms stuggle to cope with them.  So this function is
%% intended <b>only</b> for messages which have a reasonable bounded
%% size before they're formatted.
%%
%% If the format string is invalid or not enough arguments are
%% supplied a 'FORMAT ERROR' message is printed instead with the
%% offending arguments. The caller is NOT crashed.

%% @private
trace_func(#trace_func_state_v1{pid = Pid, level = Level, format_string = Fmt} = FuncState, Event, ProcState) ->
   _ = eRum:log(Level, Pid, Fmt, [Event, ProcState]),
   check_timeout(decrement_count(FuncState)).

%% @private
trace_state(Pid, Level, Options) ->
   #trace_func_state_v1{pid = Pid,
      level = Level,
      count = proplists:get_value(count, Options, infinity),
      timeout = proplists:get_value(timeout, Options, infinity),
      format_string = proplists:get_value(format_string, Options, "TRACE ~p ~p")}.

decrement_count(#trace_func_state_v1{count = infinity} = FuncState) ->
   FuncState;
decrement_count(#trace_func_state_v1{count = 1}) ->
   %% hit the counter limit
   done;
decrement_count(#trace_func_state_v1{count = Count} = FuncState) ->
   FuncState#trace_func_state_v1{count = Count - 1}.

check_timeout(#trace_func_state_v1{timeout = infinity} = FuncState) ->
   FuncState;
check_timeout(#trace_func_state_v1{timeout = Timeout, started = Started} = FuncState) ->
   case (timer:now_diff(os:timestamp(), Started) / 1000) > Timeout of
      true ->
         done;
      false ->
         FuncState
   end.