Rework supervisor tree to be more sane

src/lager.erl

@@ -16,40 +16,26 @@
 
 -module(lager).
 
--behaviour(gen_server).
-
 %% API
--export([start_link/0, start/0,
+-export([start/0,
         log/7, log/8, log/3, log/4,
-        get_loglevel/1, set_loglevel/2, set_loglevel/3]).
-
-%% callbacks
--export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
-        code_change/3]).
-
--record(state, {event_pid, handler_loglevels, error_logger_handlers}).
+        get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0,
+        minimum_loglevel/1]).
 
 %% API
 
-start_link() ->
-    Handlers = case application:get_env(lager, handlers) of
-        undefined ->
-            [{lager_console_backend, [info]},
-                {lager_file_backend, [{"log/error.log", error}, {"log/console.log", info}]}];
-        {ok, Val} ->
-            Val
-    end,
-    gen_server:start_link({local, ?MODULE}, ?MODULE, [Handlers], []).
+start() -> start(lager).
+
+start(App) ->
+    start_ok(App, application:start(App, permanent)).
 
-start() ->
-    Handlers = case application:get_env(lager, handlers) of
-        undefined ->
-            [{lager_console_backend, [info]},
-                {lager_file_backend, [{"log/error.log", error}, {"log/console.log", info}]}];
-        {ok, Val} ->
-            Val
-    end,
-    gen_server:start({local, ?MODULE}, ?MODULE, [Handlers], []).
+start_ok(_App, ok) -> ok;
+start_ok(_App, {error, {already_started, _App}}) -> ok;
+start_ok(App, {error, {not_started, Dep}}) -> 
+    ok = start(Dep),
+    start(App);
+start_ok(App, {error, Reason}) -> 
+    erlang:error({app_start_failed, App, Reason}).
 
 log(Level, Module, Function, Line, Pid, Time, Message) ->
     Timestamp = lager_util:format_time(Time),
@@ -78,82 +64,31 @@ log(Level, Pid, Format, Args) ->
             Timestamp, Msg}).
 
 set_loglevel(Handler, Level) when is_atom(Level) ->
-    gen_server:call(?MODULE, {set_loglevel, Handler, Level}).
+    Reply = gen_event:call(lager_event, Handler, {set_loglevel, Level}),
+    %% recalculate min log level
+    MinLog = minimum_loglevel(get_loglevels()),
+    lager_mochiglobal:put(loglevel, MinLog),
+    Reply.
 
 set_loglevel(Handler, Ident, Level) when is_atom(Level) ->
-    gen_server:call(?MODULE, {set_loglevel, Handler, Ident, Level}).
+    Reply = gen_event:call(lager_event, Handler, {set_loglevel, Ident, Level}),
+    %% recalculate min log level
+    MinLog = minimum_loglevel(get_loglevels()),
+    lager_mochiglobal:put(loglevel, MinLog),
+    Reply.
 
 get_loglevel(Handler) ->
-    case gen_server:call(?MODULE, {get_loglevel, Handler}) of
+    case gen_event:call(lager_event, Handler, get_loglevel) of
         X when is_integer(X) ->
             lager_util:num_to_level(X);
         Y -> Y
     end.
 
-%% gen_server callbacks
-
-init([Handlers]) ->
-    %% start a gen_event linked to this process
-    gen_event:start_link({local, lager_event}),
-    %% spin up all the defined handlers
-    [gen_event:add_sup_handler(lager_event, Module, Args) || {Module, Args} <- Handlers],
-    MinLog = minimum_log_level(get_log_levels()),
-    lager_mochiglobal:put(loglevel, MinLog),
-    case application:get_env(lager, error_logger_redirect) of
-        {ok, false} ->
-            {ok, #state{}};
-        _ ->
-            gen_event:add_sup_handler(error_logger, error_logger_lager_h, []),
-            %% TODO allow user to whitelist handlers to not be removed
-            [gen_event:delete_handler(error_logger, X, {stop_please, ?MODULE}) ||
-                X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h]],
-            {ok, #state{}}
-    end.
-
-handle_call({set_loglevel, Handler, Level}, _From, State) ->
-    Reply = gen_event:call(lager_event, Handler, {set_loglevel, Level}),
-    %% recalculate min log level
-    MinLog = minimum_log_level(get_log_levels()),
-    lager_mochiglobal:put(loglevel, MinLog),
-    {reply, Reply, State};
-handle_call({set_loglevel, Handler, Ident, Level}, _From, State) ->
-    Reply = gen_event:call(lager_event, Handler, {set_loglevel, Ident, Level}),
-    %% recalculate min log level
-    MinLog = minimum_log_level(get_log_levels()),
-    lager_mochiglobal:put(loglevel, MinLog),
-    {reply, Reply, State};
-handle_call({get_loglevel, Handler}, _From, State) ->
-    Reply = gen_event:call(lager_event, Handler, get_loglevel),
-    {reply, Reply, State};
-handle_call(_Request, _From, State) ->
-    {reply, ok, State}.
-
-handle_cast(_Request, State) ->
-    {noreply, State}.
-
-handle_info({gen_event_EXIT, error_logger_lager_h, {'EXIT', Reason}}, State) ->
-    lager:log(error, self(), ["Restarting lager error handler after it exited with ",
-            error_logger_lager_h:format_reason(Reason)]),
-    gen_event:add_sup_handler(error_logger, error_logger_lager_h, []),
-    {noreply, State};
-handle_info(Info, State) ->
-    io:format("got info ~p~n", [Info]),
-    {noreply, State}.
-
-terminate(_Reason, _State) ->
-    gen_event:stop(lager_event),
-    ok.
-
-code_change(_OldVsn, State, _Extra) ->
-    {ok, State}.
-
-%% internal functions
-
-get_log_levels() ->
+get_loglevels() ->
     [gen_event:call(lager_event, Handler, get_loglevel) ||
         Handler <- gen_event:which_handlers(lager_event)].
 
-minimum_log_level([]) ->
+minimum_loglevel([]) ->
     9; %% higher than any log level, logging off
-minimum_log_level(Levels) ->
+minimum_loglevel(Levels) ->
     erlang:hd(lists:sort(Levels)).

src/lager_app.erl

@@ -26,7 +26,32 @@ start() ->
     application:start(lager).
 
 start(_StartType, _StartArgs) ->
-    lager_sup:start_link().
+    Res = lager_sup:start_link(),
+    Handlers = case application:get_env(lager, handlers) of
+        undefined ->
+            [{lager_console_backend, [info]},
+                {lager_file_backend, [{"log/error.log", error}, {"log/console.log", info}]}];
+        {ok, Val} ->
+            Val
+    end,
+    [supervisor:start_child(lager_handler_watcher_sup, [lager_event, Module, Config]) ||
+        {Module, Config} <- Handlers],
+
+    MinLog = lager:minimum_loglevel(lager:get_loglevels()),
+    lager_mochiglobal:put(loglevel, MinLog),
+
+    case application:get_env(lager, error_logger_redirect) of
+        {ok, false} ->
+            ok;
+        _ ->
+            supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, []]),
+            %% TODO allow user to whitelist handlers to not be removed
+            [gen_event:delete_handler(error_logger, X, {stop_please, ?MODULE}) ||
+                X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h]]
+    end,
+
+    Res.
+
 
 stop(_State) ->
     ok.

src/lager_crash_log.erl

@@ -0,0 +1,168 @@
+%% Copyright (c) 2011 Basho Technologies, Inc.  All Rights Reserved.
+%%
+%% This file is provided to you under the Apache License,
+%% Version 2.0 (the "License"); you may not use this file
+%% except in compliance with the License.  You may obtain
+%% a copy of the License at
+%%
+%%   http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing,
+%% software distributed under the License is distributed on an
+%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+%% KIND, either express or implied.  See the License for the
+%% specific language governing permissions and limitations
+%% under the License.
+
+-module(lager_crash_log).
+
+-behaviour(gen_server).
+
+%% callbacks
+-export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
+        code_change/3]).
+
+-export([start_link/1, start/1]).
+
+-record(state, {
+        name,
+        fd,
+        inode
+    }).
+
+start_link(Filename) ->
+    gen_server:start_link({local, ?MODULE}, ?MODULE, [Filename], []).
+
+start(Filename) ->
+    gen_server:start({local, ?MODULE}, ?MODULE, [Filename], []).
+
+init([Filename]) ->
+    case lager_util:open_logfile(Filename, false) of
+        {ok, {FD, Inode}} ->
+            {ok, #state{name=Filename, fd=FD, inode=Inode}};
+        Error ->
+            Error
+    end.
+
+handle_call(_Call, _From, State) ->
+    {reply, ok, State}.
+
+handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode} = State) ->
+    FmtMaxBytes = 1024,
+    TermMaxSize = 500,
+    %% borrowed from riak_err
+    {ReportStr, Pid, MsgStr, _ErrorP} = case Event of
+        {error, _GL, {Pid1, Fmt, Args}} ->
+            {"ERROR REPORT", Pid1, limited_fmt(Fmt, Args, TermMaxSize, FmtMaxBytes), true};
+        {error_report, _GL, {Pid1, std_error, Rep}} ->
+            {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes), true};
+        {error_report, _GL, Other} ->
+            perhaps_a_sasl_report(error_report, Other, FmtMaxBytes);
+        _ ->
+            {ignore, ignore, ignore, false}
+    end,
+    if ReportStr == ignore ->
+            {noreply, State};
+        true ->
+            case lager_util:ensure_logfile(Name, FD, Inode, false) of
+                {ok, {NewFD, NewInode}} ->
+                    Time = [lager_util:format_time(
+                            lager_stdlib:maybe_utc(erlang:localtime())),
+                        " =", ReportStr, "====\n"],
+                    NodeSuffix = other_node_suffix(Pid),
+                    file:write(NewFD, io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix])),
+                    {noreply, State#state{fd=NewFD, inode=NewInode}};
+                Error ->
+                    lager:log(error, self(), "Failed to reopen crash log file ~w with error ~w", [Name, Error]),
+                    {noreply, State}
+            end
+    end;
+handle_cast(_Request, State) ->
+    {noreply, State}.
+
+handle_info(_Info, State) ->
+    {noreply, State}.
+
+terminate(_Reason, _State) ->
+    ok.
+
+code_change(_OldVsn, State, _Extra) ->
+    {ok, State}.
+
+%% ===== Begin code lifted from riak_err =====
+
+-spec limited_fmt(string(), list(), integer(), integer()) -> iolist().
+%% @doc Format Fmt and Args similar to what io_lib:format/2 does but with 
+%%      limits on how large the formatted string may be.
+%%
+%% If the Args list's size is larger than TermMaxSize, then the
+%% formatting is done by trunc_io:print/2, where FmtMaxBytes is used
+%% to limit the formatted string's size.
+
+limited_fmt(Fmt, Args, TermMaxSize, FmtMaxBytes) ->
+    TermSize = erts_debug:flat_size(Args),
+    if TermSize > TermMaxSize ->
+            ["Oversize args for format \"", Fmt, "\": \n",
+                [
+                    begin
+                            {Str, _} = trunc_io:print(lists:nth(N, Args), FmtMaxBytes),
+                            ["  arg", integer_to_list(N), ": ", Str, "\n"]
+                    end || N <- lists:seq(1, length(Args))
+                ]];
+        true ->
+            io_lib:format(Fmt, Args)
+    end.
+
+limited_str(Term, FmtMaxBytes) ->
+    {Str, _} = trunc_io:print(Term, FmtMaxBytes),
+    Str.
+
+other_node_suffix(Pid) when node(Pid) =/= node() ->
+    "** at node " ++ atom_to_list(node(Pid)) ++ " **\n";
+other_node_suffix(_) ->
+    "".
+
+perhaps_a_sasl_report(error_report, {Pid, Type, Report}, FmtMaxBytes) ->
+    case lager_stdlib:is_my_error_report(Type) of
+        true ->
+            {sasl_type_to_report_head(Type), Pid,
+                sasl_limited_str(Type, Report, FmtMaxBytes), true};
+        false ->
+            {ignore, ignore, ignore, false}
+    end;
+perhaps_a_sasl_report(info_report, {Pid, Type, Report}, FmtMaxBytes) ->
+    case lager_stdlib:is_my_info_report(Type) of
+        true ->
+            {sasl_type_to_report_head(Type), Pid,
+                sasl_limited_str(Type, Report, FmtMaxBytes), false};
+        false ->
+            {ignore, ignore, ignore, false}
+    end;
+perhaps_a_sasl_report(_, _, _) ->
+    {ignore, ignore, ignore, false}.
+
+sasl_type_to_report_head(supervisor_report) ->
+    "SUPERVISOR REPORT";
+sasl_type_to_report_head(crash_report) ->
+    "CRASH REPORT";
+sasl_type_to_report_head(progress) ->
+    "PROGRESS REPORT".
+
+sasl_limited_str(supervisor_report, Report, FmtMaxBytes) ->
+    Name = lager_stdlib:sup_get(supervisor, Report),
+    Context = lager_stdlib:sup_get(errorContext, Report),
+    Reason = lager_stdlib:sup_get(reason, Report),
+    Offender = lager_stdlib:sup_get(offender, Report),
+    FmtString = "     Supervisor: ~p~n     Context:    ~p~n     Reason:     "
+    "~s~n     Offender:   ~s~n~n",
+    {ReasonStr, _} = trunc_io:print(Reason, FmtMaxBytes),
+    {OffenderStr, _} = trunc_io:print(Offender, FmtMaxBytes),
+    io_lib:format(FmtString, [Name, Context, ReasonStr, OffenderStr]);
+sasl_limited_str(progress, Report, FmtMaxBytes) ->
+    [begin
+                {Str, _} = trunc_io:print(Data, FmtMaxBytes),
+                io_lib:format("    ~16w: ~s~n", [Tag, Str])
+        end || {Tag, Data} <- Report];
+sasl_limited_str(crash_report, Report, FmtMaxBytes) ->
+    lager_stdlib:proc_lib_format(Report, FmtMaxBytes).
+

src/lager_handler_watcher.erl

@@ -0,0 +1,67 @@
+-module(lager_handler_watcher).
+
+-behaviour(gen_server).
+
+%% callbacks
+-export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
+        code_change/3]).
+
+-export([start_link/3, start/3]).
+
+-record(state, {
+        module,
+        config,
+        event
+    }).
+
+start_link(Event, Module, Config) ->
+    gen_server:start_link(?MODULE, [Event, Module, Config], []).
+
+start(Event, Module, Config) ->
+    gen_server:start(?MODULE, [Event, Module, Config], []).
+
+init([Event, Module, Config]) ->
+    install_handler(Event, Module, Config),
+    {ok, #state{event=Event, module=Module, config=Config}}.
+
+handle_call(_Call, _From, State) ->
+    {reply, ok, State}.
+
+handle_cast(_Request, State) ->
+    {noreply, State}.
+
+handle_info({gen_event_EXIT, Module, normal}, #state{module=Module} = State) ->
+    {stop, normal, State};
+handle_info({gen_event_EXIT, Module, shutdown}, #state{module=Module} = State) ->
+    {stop, normal, State};
+handle_info({gen_event_EXIT, Module, Reason}, #state{module=Module,
+        config=Config, event=Event} = State) ->
+    lager:log(error, self(), "Lager event handler ~p exited with reason ~s",
+        [Module, error_logger_lager_h:format_reason(Reason)]),
+    install_handler(Event, Module, Config),
+    {noreply, State};
+handle_info(reinstall_handler, #state{module=Module, config=Config, event=Event} = State) ->
+    install_handler(Event, Module, Config),
+    {noreply, State};
+handle_info(_Info, State) ->
+    {noreply, State}.
+
+terminate(_Reason, _State) ->
+    ok.
+
+code_change(_OldVsn, State, _Extra) ->
+    {ok, State}.
+
+%% internal
+
+install_handler(Event, Module, Config) ->
+    case gen_event:add_sup_handler(Event, Module, Config) of
+        ok ->
+            lager:log(info, self(), "Lager installed handler ~p into ~p", [Module, Event]),
+            ok;
+        _ ->
+            %% try to reinstall it later
+            lager:log(error, self(), "Lager failed to install handler ~p into ~p, retrying later", [Module, Event]),
+            erlang:send_after(5000, self(), reinstall_handler)
+    end.
+

src/lager_handler_watcher_sup.erl

@@ -0,0 +1,35 @@
+%% Copyright (c) 2011 Basho Technologies, Inc.  All Rights Reserved.
+%%
+%% This file is provided to you under the Apache License,
+%% Version 2.0 (the "License"); you may not use this file
+%% except in compliance with the License.  You may obtain
+%% a copy of the License at
+%%
+%%   http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing,
+%% software distributed under the License is distributed on an
+%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+%% KIND, either express or implied.  See the License for the
+%% specific language governing permissions and limitations
+%% under the License.
+
+-module(lager_handler_watcher_sup).
+
+-behaviour(supervisor).
+
+%% API
+-export([start_link/0]).
+
+%% Callbacks
+-export([init/1]).
+
+start_link() ->
+    supervisor:start_link({local, ?MODULE}, ?MODULE, []).
+
+init([]) ->
+    {ok, {{simple_one_for_one, 1000, 3600},
+            [
+                {lager_handler_watcher, {lager_handler_watcher, start_link, []},
+                        transient, 5000, worker, [lager_handler_watcher]}
+                ]}}.

src/lager_sup.erl

@@ -28,5 +28,12 @@ start_link() ->
     supervisor:start_link({local, ?MODULE}, ?MODULE, []).
 
 init([]) ->
-    {ok, {{one_for_all, 1000, 3600},
-            [{lager, {lager, start_link, []}, permanent, 5000, worker, [lager]}]}}.
+    {ok, {{one_for_one, 1000, 3600},
+            [
+                {lager, {gen_event, start_link, [{local, lager_event}]},
+                        permanent, 5000, worker, [dynamic]},
+                {lager_crash_log, {lager_crash_log, start_link, ["log/crash.log"]},
+                    permanent, 5000, worker, [lager_crash_log]},
+                {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []},
+                    permanent, 5000, supervisor, [lager_handler_watcher_sup]}
+                ]}}.

test/lager_test_backend.erl

@@ -174,7 +174,8 @@ setup() ->
     application:load(lager),
     application:set_env(lager, handlers, [{?MODULE, [info]}]),
     application:set_env(lager, error_logger_redirect, false),
-    application:start(lager).
+    application:start(lager),
+    gen_event:call(lager_event, ?MODULE, flush).
 
 cleanup(_) ->
     application:stop(lager),