eLog/src/backend/rumBkdConsole.erl

-module(rumBkdConsole).
%% Configuration is a proplist with the following keys:
%%`level'            - log level to use
%%`use_stderr'       - either `true' or `false', defaults to false. If set to true, use standard error to output console log messages
%%`formatter'        - the module to use when formatting log messages. Defaults to `rumFormatter'
%%`formatter_config' - the format configuration string. Defaults to `time [ severity ] message'

-behaviour(gen_emm).

-include("eRum.hrl").

-ifdef(TEST).
-include_lib("eunit/include/eunit.hrl").
-compile([{parse_transform, rumTransform}]).
-endif.


-define(TERSE_FORMAT,[time, " ", color, "[", severity,"] ", message]).
-define(DEFAULT_FORMAT_CONFIG, ?TERSE_FORMAT ++ [eol()]).
-define(FORMAT_CONFIG_OFF, [{eol, eol()}]).
-define(DefOpts, [{use_stderr, false}, {group_leader, false}, {id, ?MODULE}, {formatter, rumFormatter}, {formatter_config, ?DEFAULT_FORMAT_CONFIG}]).

-export([
   init/1
   , handleCall/2
   , handleEvent/2
   , handleInfo/2
   , terminate/2
   , code_change/3
]).

-record(state, {
   level :: {'mask', integer()},
   out = user :: user | standard_error | pid(),
   id :: atom() | {atom(), any()},
   formatter :: atom(),
   format_config :: any(),
   colors = [] :: list()
}).


init(Opts) ->
   case  isNewStyleConsole() of
      false ->
         Msg = "Lager's console backend is incompatible with the 'old' shell, not enabling it",
         %% be as noisy as possible, log to every possible place
         try
            alarm_handler:set_alarm({?MODULE, "WARNING: " ++ Msg})
         catch
            _:_ ->
               error_logger:warning_msg(Msg ++ "~n")
         end,
         io:format("WARNING: " ++ Msg ++ "~n"),
         ?INT_LOG(warning, Msg, []),
         {error, {fatal, old_shell}};
      _ ->
         true = checkOpts(Opts),
         Colors = ?IIF(rumUtil:get_env(colored, false), rumUtil:get_env(colors, []), []),
         Level = rumUtil:get_opt(level, Opts, undefined),
         L = rumUtil:config_to_mask(Level),
         [UseErr, GroupLeader, ID, Formatter, Config] = [rumUtil:get_opt(Key, Opts, Def) || {Key, Def} <- ?DefOpts],
         Out = ?IIF(UseErr, standard_error, ?IIF(GroupLeader == false, user, begin erlang:monitor(process, GroupLeader), GroupLeader end)),
         {ok, #state{level = L, id = ID, out = Out, formatter = Formatter, format_config = Config, colors = Colors}}
   end.

checkOpts([]) -> true;
checkOpts([{level, L} | T]) when is_atom(L) ->
   ?IIF(lists:member(L, ?RumLevels) == false,  throw({error, {fatal, {bad_level, L}}}), checkOpts(T));
checkOpts([{use_stderr, true} | T]) ->
   checkOpts(T);
checkOpts([{use_stderr, false} | T]) ->
   checkOpts(T);
checkOpts([{formatter, M} | T]) when is_atom(M) ->
   checkOpts(T);
checkOpts([{formatter_config, C} | T]) when is_list(C) ->
   checkOpts(T);
checkOpts([{group_leader, L} | T]) when is_pid(L) ->
   checkOpts(T);
checkOpts([{id, {?MODULE, _}} | T]) ->
   checkOpts(T);
checkOpts([H | _]) ->
   throw({error, {fatal, {bad_console_config, H}}}).

handleCall(mGetLogLevel, #state{level = Level} = State) ->
   {ok, Level, State};
handleCall({mSetLogLevel, Level}, State) ->
   try rumUtil:config_to_mask(Level) of
      Levels ->
         {ok, ok, State#state{level = Levels}}
   catch
      _:_ ->
         {ok, {error, bad_log_level}, State}
   end;
handleCall(_Request, State) ->
   {ok, ok, State}.

%% @private
handleEvent({mWriteLog, Message},
   #state{level = L, out = Out, formatter = Formatter, format_config = FormatConfig, colors = Colors, id = ID} = State) ->
   case rumUtil:is_loggable(Message, L, ID) of
      true ->
         io:put_chars(Out, Formatter:format(Message, FormatConfig, Colors)),
         {ok, State};
      false ->
         {ok, State}
   end;
handleEvent(_Event, State) ->
   {ok, State}.

handleInfo({'DOWN', _, process, Out, _}, #state{out = Out}) ->
   remove_handler;
handleInfo(_Info, State) ->
   {ok, State}.

terminate(remove_handler, _State = #state{id = ID}) ->
   %% have to do this asynchronously because we're in the event handlr
   spawn(fun() -> eRum:clear_trace_by_destination(ID) end),
   ok;
terminate(_Reason, _State) ->
   ok.

code_change(_OldVsn, State, _Extra) ->
   {ok, State}.

eol() ->
   case application:get_env(lager, colored) of
      {ok, true} ->
         "\e[0m\r\n";
      _ ->
         "\r\n"
   end.

isNewStyleConsole() ->
   %% Criteria:
   %% 1. If the user has specified '-noshell' on the command line,
   %%    then we will pretend that the new-style console is available.
   %%    If there is no shell at all, then we don't have to worry
   %%    about log events being blocked by the old-style shell.
   %% 2. Windows doesn't support the new shell, so all windows users
   %%    have is the oldshell.
   %% 3. If the user_drv process is registered, all is OK.
   %%    'user_drv' is a registered proc name used by the "new"
   %%    console driver.
   init:get_argument(noshell) /= error orelse element(1, os:type()) /= win32 orelse is_pid(whereis(user_drv)).

-ifdef(TEST).
console_config_validation_test_() ->
   Good = [{level, info}, {use_stderr, true}],
   Bad1 = [{level, foo}, {use_stderr, flase}],
   Bad2 = [{level, info}, {use_stderr, flase}],
   AllGood = [{level, info}, {formatter, my_formatter},
      {formatter_config, ["blort", "garbage"]},
      {use_stderr, false}],
   [
      ?_assertEqual(true, checkOpts(Good)),
      ?_assertThrow({error, {fatal, {bad_level, foo}}}, checkOpts(Bad1)),
      ?_assertThrow({error, {fatal, {bad_console_config, {use_stderr, flase}}}}, checkOpts(Bad2)),
      ?_assertEqual(true, checkOpts(AllGood))
   ].

console_log_test_() ->
   %% tiny recursive fun that pretends to be a group leader
   F = fun(Self) ->
      fun() ->
         YComb = fun(Fun) ->
            receive
               {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} = Y ->
                  From ! {io_reply, ReplyAs, ok},
                  Self ! Y,
                  Fun(Fun);
               Other ->
                  ?debugFmt("unexpected message ~p~n", [Other]),
                  Self ! Other
            end
                 end,
         YComb(YComb)
      end
       end,
   {foreach,
      fun() ->
         error_logger:tty(false),
         application:load(lager),
         application:set_env(lager, handlers, []),
         application:set_env(lager, errLoggerRedirect, false),
         eRum:start(),
         whereis(user)
      end,
      fun(User) ->
         unregister(user),
         register(user, User),
         application:stop(lager),
         application:stop(goldrush),
         error_logger:tty(true)
      end,
      [
         {"regular console logging",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               erlang:group_leader(Pid, whereis(rumEvent)),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:log(info, self(), "Test message"),
               receive
                  {io_request, From, ReplyAs, {put_chars, unicode, Msg}} ->
                     From ! {io_reply, ReplyAs, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[info]", TestMsg], re:split(Msg, " ", [{return, list}, {parts, 3}]))
               after
                  500 ->
                     ?assert(false)
               end
            end
         },
         {"verbose console logging",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               erlang:group_leader(Pid, whereis(rumEvent)),
               gen_event:add_handler(rumEvent, lager_console_backend, [info, true]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:info("Test message"),
               PidStr = pid_to_list(self()),
               receive
                  {io_request, _, _, {put_chars, unicode, Msg}} ->
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, _, "[info]", PidStr, _, TestMsg], re:split(Msg, "[ @]", [{return, list}, {parts, 6}]))
               after
                  500 ->
                     ?assert(false)
               end
            end
         },
         {"custom format console logging",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               erlang:group_leader(Pid, whereis(rumEvent)),
               gen_event:add_handler(rumEvent, lager_console_backend,
                  [{level, info}, {formatter, lager_default_formatter}, {formatter_config, [date, "#", time, "#", severity, "#", node, "#", pid, "#",
                     module, "#", function, "#", file, "#", line, "#", message, "\r\n"]}]),
               rumConfig:set({rumEvent, loglevel}, {?INFO, []}),
               eRum:info("Test message"),
               PidStr = pid_to_list(self()),
               NodeStr = atom_to_list(node()),
               ModuleStr = atom_to_list(?MODULE),
               receive
                  {io_request, _, _, {put_chars, unicode, Msg}} ->
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, _, "info", NodeStr, PidStr, ModuleStr, _, _, _, TestMsg],
                        re:split(Msg, "#", [{return, list}, {parts, 10}]))
               after
                  500 ->
                     ?assert(false)
               end
            end
         },
         {"tracing should work",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]),
               erlang:group_leader(Pid, whereis(rumEvent)),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:debug("Test message"),
               receive
                  {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} ->
                     From ! {io_reply, ReplyAs, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end,
               {ok, _} = eRum:trace_console([{module, ?MODULE}]),
               eRum:debug("Test message"),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  500 ->
                     ?assert(false)
               end
            end
         },
         {"tracing doesn't duplicate messages",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               erlang:group_leader(Pid, whereis(rumEvent)),
               eRum:debug("Test message"),
               receive
                  {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} ->
                     From ! {io_reply, ReplyAs, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end,
               {ok, _} = eRum:trace_console([{module, ?MODULE}]),
               eRum:error("Test message"),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[error]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  1000 ->
                     ?assert(false)
               end,
               %% make sure this event wasn't duplicated
               receive
                  {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} ->
                     From2 ! {io_reply, ReplyAs2, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end
            end
         },
         {"blacklisting a loglevel works",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:set_loglevel(lager_console_backend, '!=info'),
               erlang:group_leader(Pid, whereis(rumEvent)),
               eRum:debug("Test message"),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  1000 ->
                     ?assert(false)
               end,
               %% info is blacklisted
               eRum:info("Test message"),
               receive
                  {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} ->
                     From2 ! {io_reply, ReplyAs2, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end
            end
         },
         {"whitelisting a loglevel works",
            fun() ->
               Pid = spawn(F(self())),
               unregister(user),
               register(user, Pid),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:set_loglevel(lager_console_backend, '=debug'),
               erlang:group_leader(Pid, whereis(rumEvent)),
               eRum:debug("Test message"),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  1000 ->
                     ?assert(false)
               end,
               %% info is blacklisted
               eRum:error("Test message"),
               receive
                  {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} ->
                     From2 ! {io_reply, ReplyAs2, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end
            end
         },
         {"console backend with custom group leader",
            fun() ->
               Pid = spawn(F(self())),
               gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}, {group_leader, Pid}]),
               rumConfig:set({rumEvent, loglevel}, {element(2, rumUtil:config_to_mask(info)), []}),
               eRum:info("Test message"),
               ?assertNotEqual({group_leader, Pid}, erlang:process_info(whereis(rumEvent), group_leader)),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[info]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  1000 ->
                     ?assert(false)
               end,
               %% killing the pid should prevent any new log messages (to prove we haven't accidentally redirected
               %% the group leader some other way
               exit(Pid, kill),
               timer:sleep(100),
               %% additionally, check the lager backend has been removed (because the group leader process died)
               ?assertNot(lists:member(lager_console_backend, gen_event:which_handlers(rumEvent))),
               eRum:error("Test message"),
               receive
                  {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} ->
                     From2 ! {io_reply, ReplyAs2, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end
            end
         },
         {"console backend with custom group leader using a trace and an ID",
            fun() ->
               Pid = spawn(F(self())),
               ID = {?MODULE, trace_test},
               Handlers = rumConfig:global_get(handlers, []),
               HandlerInfo = lager_app:start_handler(rumEvent, ID,
                  [{level, none}, {group_leader, Pid},
                     {id, ID}]),
               rumConfig:global_set(handlers, [HandlerInfo | Handlers]),
               eRum:info("Test message"),
               ?assertNotEqual({group_leader, Pid}, erlang:process_info(whereis(rumEvent), group_leader)),
               receive
                  {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} ->
                     From ! {io_reply, ReplyAs, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end,
               eRum:trace(ID, [{module, ?MODULE}], debug),
               eRum:info("Test message"),
               receive
                  {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                     From1 ! {io_reply, ReplyAs1, ok},
                     TestMsg = "Test message" ++ eol(),
                     ?assertMatch([_, "[info]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
               after
                  500 ->
                     ?assert(false)
               end,
               ?assertNotEqual({0, []}, rumConfig:get({rumEvent, loglevel})),
               %% killing the pid should prevent any new log messages (to prove we haven't accidentally redirected
               %% the group leader some other way
               exit(Pid, kill),
               timer:sleep(100),
               %% additionally, check the lager backend has been removed (because the group leader process died)
               ?assertNot(lists:member(lager_console_backend, gen_event:which_handlers(rumEvent))),
               %% finally, check the trace has been removed
               ?assertEqual({0, []}, rumConfig:get({rumEvent, loglevel})),
               eRum:error("Test message"),
               receive
                  {io_request, From3, ReplyAs3, {put_chars, unicode, _Msg3}} ->
                     From3 ! {io_reply, ReplyAs3, ok},
                     ?assert(false)
               after
                  500 ->
                     ?assert(true)
               end
            end
         }
      ]
   }.

set_loglevel_test_() ->
   {foreach,
      fun() ->
         error_logger:tty(false),
         application:load(lager),
         application:set_env(lager, handlers, [{lager_console_backend, [{level, info}]}]),
         application:set_env(lager, errLoggerRedirect, false),
         eRum:start()
      end,
      fun(_) ->
         application:stop(lager),
         application:stop(goldrush),
         error_logger:tty(true)
      end,
      [
         {"Get/set loglevel test",
            fun() ->
               ?assertEqual(info, eRum:get_loglevel(lager_console_backend)),
               eRum:set_loglevel(lager_console_backend, debug),
               ?assertEqual(debug, eRum:get_loglevel(lager_console_backend)),
               eRum:set_loglevel(lager_console_backend, '!=debug'),
               ?assertEqual(info, eRum:get_loglevel(lager_console_backend)),
               eRum:set_loglevel(lager_console_backend, '!=info'),
               ?assertEqual(debug, eRum:get_loglevel(lager_console_backend)),
               ok
            end
         },
         {"Get/set invalid loglevel test",
            fun() ->
               ?assertEqual(info, eRum:get_loglevel(lager_console_backend)),
               ?assertEqual({error, bad_log_level},
                  eRum:set_loglevel(lager_console_backend, fatfinger)),
               ?assertEqual(info, eRum:get_loglevel(lager_console_backend))
            end
         }

      ]
   }.

-endif.