Merge branch 'adt-improve-test-coverage'

Makefile

@@ -15,7 +15,7 @@ distclean: clean
 	./rebar delete-deps
 
 test:
-	./rebar eunit
+	./rebar compile eunit
 
 ##
 ## Doc targets

include/lager.hrl

@@ -54,12 +54,42 @@
 -define(SHOULD_LOG(Level),
     lager_util:level_to_num(Level) =< lager_mochiglobal:get(loglevel, ?LOG_NONE)).
 
+-define(NOTIFY(Level, Pid, Format, Args),
+    gen_event:notify(lager_event, {log, lager_util:level_to_num(Level),
+            lager_util:format_time(), [io_lib:format("[~p] ", [Level]),
+                io_lib:format("~p ", [Pid]), io_lib:format(Format, Args)]})).
+
+%% FOR INTERNAL USE ONLY
 %% internal non-blocking logging call
+%% there's some special handing for when we try to log (usually errors) while
+%% lager is still starting.
+-ifdef(TEST).
 -define(INT_LOG(Level, Format, Args),
     case ?SHOULD_LOG(Level) of
         true ->
-            gen_event:notify(lager_event, {log, lager_util:level_to_num(Level),
-                    lager_util:format_time(), [io_lib:format("[~p] ~p ", [Level, self()]), io_lib:format(Format, Args)]});
-         class="p">_  class="o">-> ok
+            ?NOTIFY(Level, self(), Format, Args);
+        _ ->;
+            ok
     end).
-
+-else.
+-define(INT_LOG(Level, Format, Args),
+    Self = self(),
+    %% do this in a spawn so we don't cause a deadlock calling gen_event:which_handlers
+    %% from a gen_event handler
+    spawn(fun() ->
+            case catch(gen_event:which_handlers(lager_event)) of
+                X when X == []; X == {'EXIT', noproc} ->
+                    %% there's no handlers yet or lager isn't running, try again
+                    %% in half a second.
+                    timer:sleep(500),
+                    ?NOTIFY(Level, Self, Format, Args);
+                _ ->
+                    case ?SHOULD_LOG(Level) of
+                        true ->
+                            ?NOTIFY(Level, Self, Format, Args);
+                        _ ->
+                            ok
+                    end
+            end
+    end)).
+-endif.

src/lager_app.erl

@@ -21,6 +21,7 @@
 -module(lager_app).
 
 -behaviour(application).
+-include("lager.hrl").
 
 -export([start/0,
          start/2,
@@ -30,6 +31,8 @@ start() ->
     application:start(lager).
 
 start(_StartType, _StartArgs) ->
+    %% until lager is completely started, allow all messages to go through
+    lager_mochiglobal:put(loglevel, ?DEBUG),
     {ok, Pid} = lager_sup:start_link(),
     Handlers = case application:get_env(lager, handlers) of
         undefined ->
@@ -42,6 +45,7 @@ start(_StartType, _StartArgs) ->
     [supervisor:start_child(lager_handler_watcher_sup, [lager_event, Module, Config]) ||
         {Module, Config} <- Handlers],
 
+    %% mask the messages we have no use for
     MinLog = lager:minimum_loglevel(lager:get_loglevels()),
     lager_mochiglobal:put(loglevel, MinLog),
 

src/lager_console_backend.erl

@@ -26,17 +26,39 @@
 
 -record(state, {level, verbose}).
 
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-endif.
+
+-include("lager.hrl").
+
 %% @private
 init(Level) when is_atom(Level) ->
-    {ok, #state{level=lager_util:level_to_num(Level), verbose=false}};
+    case lists:member(Level, ?LEVELS) of
+        true ->
+            {ok, #state{level=lager_util:level_to_num(Level), verbose=false}};
+        _ ->
+            {error, bad_log_level}
+    end;
 init([Level, Verbose]) ->
-    {ok, #state{level=lager_util:level_to_num(Level), verbose=Verbose}}.
+    case lists:member(Level, ?LEVELS) of
+        true ->
+            {ok, #state{level=lager_util:level_to_num(Level), verbose=Verbose}};
+        _ ->
+            {error, bad_log_level}
+    end.
+
 
 %% @private
 handle_call(get_loglevel, #state{level=Level} = State) ->
     {ok, Level, State};
 handle_call({set_loglevel, Level}, State) ->
-    {ok, ok, State#state{level=lager_util:level_to_num(Level)}};
+    case lists:member(Level, ?LEVELS) of
+        true ->
+            {ok, ok, State#state{level=lager_util:level_to_num(Level)}};
+        _ ->
+            {ok, {error, bad_log_level}, State}
+    end;
 handle_call(_Request, State) ->
     {ok, ok, State}.
 
@@ -64,3 +86,109 @@ terminate(_Reason, _State) ->
 %% @private
 code_change(_OldVsn, State, _Extra) ->
     {ok, State}.
+
+-ifdef(TEST).
+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, error_logger_redirect, false),
+                application:start(lager)
+        end,
+        fun(_) ->
+                application:stop(lager),
+                application:unload(lager),
+                error_logger:tty(true)
+        end,
+        [
+            {"regular console logging",
+                fun() ->
+                        Pid = spawn(F(self())),
+                        gen_event:add_handler(lager_event, lager_console_backend, info),
+                        erlang:group_leader(Pid, whereis(lager_event)),
+                        lager:log(info, self(), "Test message"),
+                        receive
+                            {io_request, From, ReplyAs, {put_chars, unicode, Msg}} ->
+                                From ! {io_reply, ReplyAs, ok},
+                                ?assertMatch([_, "[info]", "Test message\n"], re:split(Msg, " ", [{return, list}, {parts, 3}]))
+                        after
+                            500 ->
+                                ?assert(false)
+                        end
+                end
+            },
+            {"verbose console logging",
+                fun() ->
+                        Pid = spawn(F(self())),
+                        erlang:group_leader(Pid, whereis(lager_event)),
+                        gen_event:add_handler(lager_event, lager_console_backend, [info, true]),
+                        lager:log(info, self(), "Test message"),
+                        lager:log(info, self(), "Test message"),
+                        PidStr = pid_to_list(self()),
+                        receive
+                            {io_request, _, _, {put_chars, unicode, Msg}} ->
+                                ?assertMatch([_, _, "[info]", PidStr, "Test message\n"], re:split(Msg, " ", [{return, list}, {parts, 5}]))
+                        after
+                            500 ->
+                                ?assert(false)
+                        end
+                end
+            }
+        ]
+    }.
+
+set_loglevel_test_() ->
+    {foreach,
+        fun() ->
+                error_logger:tty(false),
+                application:load(lager),
+                application:set_env(lager, handlers, [{lager_console_backend, info}]),
+                application:set_env(lager, error_logger_redirect, false),
+                application:start(lager)
+        end,
+        fun(_) ->
+                application:stop(lager),
+                application:unload(lager),
+                error_logger:tty(true)
+        end,
+        [
+            {"Get/set loglevel test",
+                fun() ->
+                        ?assertEqual(info, lager:get_loglevel(lager_console_backend)),
+                        lager:set_loglevel(lager_console_backend, debug),
+                        ?assertEqual(debug, lager:get_loglevel(lager_console_backend))
+                end
+            },
+            {"Get/set invalid loglevel test",
+                fun() ->
+                        ?assertEqual(info, lager:get_loglevel(lager_console_backend)),
+                        ?assertEqual({error, bad_log_level},
+                            lager:set_loglevel(lager_console_backend, fatfinger)),
+                        ?assertEqual(info, lager:get_loglevel(lager_console_backend))
+                end
+            }
+
+        ]
+    }.
+
+-endif.

src/lager_crash_log.erl

@@ -33,6 +33,11 @@
 
 -behaviour(gen_server).
 
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-include_lib("kernel/include/file.hrl").
+-endif.
+
 %% callbacks
 -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
         code_change/3]).
@@ -67,8 +72,11 @@ init([Filename, MaxBytes, Size, Date, Count]) ->
             schedule_rotation(Date),
             {ok, #state{name=Filename, fd=FD, inode=Inode,
                     fmtmaxbytes=MaxBytes, size=Size, count=Count, date=Date}};
-        Error ->
-            Error
+        {error, Reason} ->
+            ?INT_LOG(error, "Failed to open crash log file ~s with error: ~s",
+                [Filename, file:format_error(Reason)]),
+            {ok, #state{name=Filename, fmtmaxbytes=MaxBytes, flap=true,
+                    size=Size, count=Count, date=Date}}
     end.
 
 %% @private
@@ -117,7 +125,7 @@ handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap,
                         true ->
                             {noreply, State};
                         _ ->
-                            ?INT_LOG(error, "Failed to reopen logfile ~s with error ~w",
+                            ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s",
                                 [Name, file:format_error(Reason)]),
                             {noreply, State#state{flap=true}}
                     end
@@ -213,3 +221,111 @@ sasl_limited_str(progress, Report, FmtMaxBytes) ->
 sasl_limited_str(crash_report, Report, FmtMaxBytes) ->
     lager_stdlib:proc_lib_format(Report, FmtMaxBytes).
 
+-ifdef(TEST).
+
+filesystem_test_() ->
+    {foreach,
+        fun() ->
+                file:write_file("crash_test.log", ""),
+                error_logger:tty(false),
+                application:load(lager),
+                application:set_env(lager, handlers, [{lager_test_backend, info}]),
+                application:set_env(lager, error_logger_redirect, true),
+                application:unset_env(lager, crash_log),
+                application:start(lager),
+                timer:sleep(100),
+                lager_test_backend:flush()
+        end,
+        fun(_) ->
+                case whereis(lager_crash_log) of
+                    P when is_pid(P) ->
+                        exit(P, kill);
+                    _ -> ok
+                end,
+                file:delete("crash_test.log"),
+                application:stop(lager),
+                application:unload(lager),
+                error_logger:tty(true)
+        end,
+        [
+            {"under normal circumstances, file should be opened",
+                fun() ->
+                        {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
+                        error_logger:error_msg("Test message\n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("crash_test.log"),
+                        ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}]))
+                end
+            },
+            {"file can't be opened on startup triggers an error message",
+                fun() ->
+                        {ok, FInfo} = file:read_file_info("crash_test.log"),
+                        file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}),
+                        {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message))
+                end
+            },
+            {"file that becomes unavailable at runtime should trigger an error message",
+                fun() ->
+                        {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        error_logger:error_msg("Test message\n"),
+                        timer:sleep(100),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        file:delete("crash_test.log"),
+                        file:write_file("crash_test.log", ""),
+                        {ok, FInfo} = file:read_file_info("crash_test.log"),
+                        file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}),
+                        error_logger:error_msg("Test message\n"),
+                        timer:sleep(100),
+                        ?assertEqual(3, lager_test_backend:count()),
+                        lager_test_backend:pop(),
+                        lager_test_backend:pop(),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to reopen crash log crash_test.log with error: permission denied", lists:flatten(Message))
+                end
+            },
+            {"unavailable files that are fixed at runtime should start having log messages written",
+                fun() ->
+                        {ok, FInfo} = file:read_file_info("crash_test.log"),
+                        OldPerms = FInfo#file_info.mode,
+                        file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}),
+                        {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)),
+                        file:write_file_info("crash_test.log", FInfo#file_info{mode = OldPerms}),
+                        error_logger:error_msg("Test message~n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("crash_test.log"),
+                        ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}]))
+                end
+            },
+            {"external logfile rotation/deletion should be handled",
+                fun() ->
+                        {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        error_logger:error_msg("Test message~n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("crash_test.log"),
+                        ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])),
+                        file:delete("crash_test.log"),
+                        file:write_file("crash_test.log", ""),
+                        error_logger:error_msg("Test message1~n"),
+                        timer:sleep(100),
+                        {ok, Bin1} = file:read_file("crash_test.log"),
+                        ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])),
+                        file:rename("crash_test.log", "crash_test.log.0"),
+                        error_logger:error_msg("Test message2~n"),
+                        timer:sleep(100),
+                        {ok, Bin2} = file:read_file("crash_test.log"),
+                        ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}]))
+                end
+            }
+        ]
+    }.
+
+-endif.
+

src/lager_file_backend.erl

@@ -34,9 +34,8 @@
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
--endif.
-
 -include_lib("kernel/include/file.hrl").
+-endif.
 
 -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
         code_change/3]).
@@ -168,7 +167,7 @@ write(#file{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize,
                 true ->
                     File;
                 _ ->
-                    ?INT_LOG(error, "Failed to reopen logfile ~s with error ~s",
+                    ?INT_LOG(error, "Failed to reopen log file ~s with error ~s",
                         [Name, file:format_error(Reason)]),
                     File#file{flap=true}
             end
@@ -176,6 +175,15 @@ write(#file{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize,
 
 validate_logfiles([]) ->
     [];
+validate_logfiles([{Name, Level}|T]) ->
+    case lists:member(Level, ?LEVELS) of
+        true ->
+            [{Name, Level, 0, undefined, 0}|validate_logfiles(T)];
+        _ ->
+            ?INT_LOG(error, "Invalid log level of ~p for ~s.",
+                [Level, Name]),
+            validate_logfiles(T)
+    end;
 validate_logfiles([{Name, Level, Size, Date, Count}|T]) ->
     ValidLevel = (lists:member(Level, ?LEVELS)),
     ValidSize = (is_integer(Size) andalso Size >= 0),
@@ -209,7 +217,7 @@ validate_logfiles([{Name, Level, Size, Date, Count}|T]) ->
             end
     end;
 validate_logfiles([H|T]) ->
-    ?INT_LOG(error, "Invalid logfile config ~p.", [H]),
+    ?INT_LOG(error, "Invalid log file config ~p.", [H]),
     validate_logfiles(T).
 
 schedule_rotation(_, undefined) ->
@@ -248,5 +256,123 @@ rotation_test() ->
     ?assertMatch(#file{name="test.log", level=?DEBUG}, Result2),
     ok.
 
+filesystem_test_() ->
+    {foreach,
+        fun() ->
+                file:write_file("test.log", ""),
+                error_logger:tty(false),
+                application:load(lager),
+                application:set_env(lager, handlers, [{lager_test_backend, info}]),
+                application:set_env(lager, error_logger_redirect, false),
+                application:start(lager)
+        end,
+        fun(_) ->
+                file:delete("test.log"),
+                application:stop(lager),
+                application:unload(lager),
+                error_logger:tty(true)
+        end,
+        [
+            {"under normal circumstances, file should be opened",
+                fun() ->
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        lager:log(error, self(), "Test message"),
+                        {ok, Bin} = file:read_file("test.log"),
+                        Pid = pid_to_list(self()),
+                        ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}]))
+                end
+            },
+            {"file can't be opened on startup triggers an error message",
+                fun() ->
+                        {ok, FInfo} = file:read_file_info("test.log"),
+                        file:write_file_info("test.log", FInfo#file_info{mode = 0}),
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message))
+                end
+            },
+            {"file that becomes unavailable at runtime should trigger an error message",
+                fun() ->
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        lager:log(error, self(), "Test message"),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        file:delete("test.log"),
+                        file:write_file("test.log", ""),
+                        {ok, FInfo} = file:read_file_info("test.log"),
+                        file:write_file_info("test.log", FInfo#file_info{mode = 0}),
+                        lager:log(error, self(), "Test message"),
+                        timer:sleep(100),
+                        ?assertEqual(3, lager_test_backend:count()),
+                        lager_test_backend:pop(),
+                        lager_test_backend:pop(),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to reopen log file test.log with error permission denied", lists:flatten(Message))
+                end
+            },
+            {"unavailable files that are fixed at runtime should start having log messages written",
+                fun() ->
+                        {ok, FInfo} = file:read_file_info("test.log"),
+                        OldPerms = FInfo#file_info.mode,
+                        file:write_file_info("test.log", FInfo#file_info{mode = 0}),
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)),
+                        file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}),
+                        lager:log(error, self(), "Test message"),
+                        {ok, Bin} = file:read_file("test.log"),
+                        Pid = pid_to_list(self()),
+                        ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}]))
+                end
+            },
+            {"external logfile rotation/deletion should be handled",
+                fun() ->
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        lager:log(error, self(), "Test message1"),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        file:delete("test.log"),
+                        file:write_file("test.log", ""),
+                        lager:log(error, self(), "Test message2"),
+                        {ok, Bin} = file:read_file("test.log"),
+                        Pid = pid_to_list(self()),
+                        ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])),
+                        file:rename("test.log", "test.log.0"),
+                        lager:log(error, self(), "Test message3"),
+                        {ok, Bin2} = file:read_file("test.log"),
+                        ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}]))
+                end
+            },
+            {"runtime level changes",
+                fun() ->
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        lager:log(info, self(), "Test message1"),
+                        lager:log(error, self(), "Test message2"),
+                        {ok, Bin} = file:read_file("test.log"),
+                        Lines = length(re:split(Bin, "\n", [{return, list}, trim])),
+                        ?assertEqual(Lines, 2),
+                        ?assertEqual(ok, lager:set_loglevel(lager_file_backend, "test.log", warning)),
+                        lager:log(info, self(), "Test message3"), %% this won't get logged
+                        lager:log(error, self(), "Test message4"),
+                        {ok, Bin2} = file:read_file("test.log"),
+                        Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])),
+                        ?assertEqual(Lines2, 3)
+                end
+            },
+            {"invalid runtime level changes",
+                fun() ->
+                        gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]),
+                        ?assertEqual({error, bad_identifier}, lager:set_loglevel(lager_file_backend, "test2.log", warning)),
+                        ?assertEqual({error, missing_identifier}, lager:set_loglevel(lager_file_backend, warning))
+                end
+            }
+
+        ]
+    }.
+
+
 -endif.
 

src/lager_handler_watcher.erl

@@ -23,6 +23,10 @@
 
 -behaviour(gen_server).
 
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-endif.
+
 %% callbacks
 -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
         code_change/3]).
@@ -87,3 +91,67 @@ install_handler(Event, Module, Config) ->
             erlang:send_after(5000, self(), reinstall_handler)
     end.
 
+-ifdef(TEST).
+
+from_now(Seconds) ->
+    {Mega, Secs, Micro} = os:timestamp(),
+    {Mega, Secs + Seconds, Micro}.
+
+reinstall_on_initial_failure_test_() ->
+    {timeout, 60000,
+        [
+            fun() ->
+                    error_logger:tty(false),
+                    application:load(lager),
+                    application:set_env(lager, handlers, [{lager_test_backend, info}, {lager_crash_backend, [from_now(2), undefined]}]),
+                    application:set_env(lager, error_logger_redirect, false),
+                    application:unset_env(lager, crash_log),
+                    application:start(lager),
+                    try
+                      ?assertEqual(1, lager_test_backend:count()),
+                      {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                      ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :"++_, Message),
+                      ?assertEqual(0, lager_test_backend:count()),
+                      timer:sleep(6000),
+                      ?assertEqual(0, lager_test_backend:count()),
+                      ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(lager_event)))
+                    after
+                      application:stop(lager),
+                      application:unload(lager),
+                      error_logger:tty(true)
+                    end
+            end
+        ]
+    }.
+
+reinstall_on_runtime_failure_test_() ->
+    {timeout, 60000,
+        [
+            fun() ->
+                    error_logger:tty(false),
+                    application:load(lager),
+                    application:set_env(lager, handlers, [{lager_test_backend, info}, {lager_crash_backend, [undefined, from_now(5)]}]),
+                    application:set_env(lager, error_logger_redirect, false),
+                    application:unset_env(lager, crash_log),
+                    application:start(lager),
+                    try
+                        ?assertEqual(0, lager_test_backend:count()),
+                        ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(lager_event))),
+                        timer:sleep(6000),
+                        ?assertEqual(2, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Lager event handler lager_crash_backend exited with reason crash", Message),
+                        {_Level2, _Time2, [_, _, Message2]} = lager_test_backend:pop(),
+                        ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :"++_, Message2),
+                        ?assertEqual(false, lists:member(lager_crash_backend, gen_event:which_handlers(lager_event)))
+                    after
+                       application:stop(lager),
+                       application:unload(lager),
+                       error_logger:tty(true)
+                   end
+            end
+        ]
+    }.
+
+
+-endif.

src/lager_trunc_io.erl

@@ -34,9 +34,13 @@
 -author('matthias@corelatus.se').
 %% And thanks to Chris Newcombe for a bug fix 
 -export([format/3, print/2, fprint/2, safe/2]).               % interface functions
--export([perf/0, perf/3, perf1/0, test/0, test/2]). % testing functions
 -version("$Id: trunc_io.erl,v 1.11 2009-02-23 12:01:06 matthias Exp $").
 
+-ifdef(TEST).
+-export([perf/0, perf/3, perf1/0, test/0, test/2]). % testing functions
+-include_lib("eunit/include/eunit.hrl").
+-endif.
+
 format(String, Args, Max) ->
     Parts = re:split(String,
         "(~(?:-??\\d+\\.|\\*\\.|\\.|)(?:-??\\d+\\.|\\*\\.|\\.|)(?:-??\\d+|\\*|)(?:t|)(?:[cfegswpWPBX#bx+ni~]))",
@@ -66,11 +70,16 @@ format([[$~|H]| T], [AH1, _AH2 | AT], Max, Acc, ArgAcc) when H == "W"; H == "P"
     %% trunc_io isn't (yet) depth aware, so we can't honor this format string
     %% safely at the moment, so just treat it like a regular ~p
     %% TODO support for depth limiting
-    case print(AH1, Max + 2) of
+    Input = case H == "P" andalso lager_stdlib:string_p(AH1) of
+        true ->
+            lists:flatten(AH1);
+        _ -> AH1
+    end,
+    case print(Input, Max + 2) of
         {_Res, Max} ->
             % this isn't the last argument, but it consumed all available space
             % delay calculating the print size until the end
-            format(T, AT, Max + 2, ["~s" | Acc], [{future, AH1} | ArgAcc]);
+            format(T, AT, Max + 2, ["~s" | Acc], [{future, Input} | ArgAcc]);
         {String, Length} ->
             format(T, AT, Max + 2 - Length, ["~s" | Acc], [String | ArgAcc])
     end;
@@ -78,12 +87,17 @@ format([[$~|H]| T], [AH | AT], Max, Acc, ArgAcc) when length(H) == 1 ->
     % single character format specifier, relatively simple
     case H of
         _ when H == "p"; H == "w"; H == "s" ->
+            Input = case (H == "s" orelse H == "p") andalso lager_stdlib:string_p(AH) of
+                true ->
+                    lists:flatten(AH);
+                _ -> AH
+            end,
             %okay, these are prime candidates for rewriting
-            case print(AH, Max + 2) of
+            case print(Input, Max + 2) of
                 {_Res, Max} ->
                     % this isn't the last argument, but it consumed all available space
                     % delay calculating the print size until the end
-                    format(T, AT, Max + 2, ["~s" | Acc], [{future, AH} | ArgAcc]);
+                    format(T, AT, Max + 2, ["~s" | Acc], [{future, Input} | ArgAcc]);
                 {String, Length} ->
                     {Value, RealLen} = case H of
                         "s" ->
@@ -103,14 +117,19 @@ format([[$~|H]| T], [AH | AT], Max, Acc, ArgAcc) ->
     case lists:nth(length(H), H) of
         C when C == $p; C == $w; C == $s ->
             %okay, these are prime candidates for rewriting
-            case print(AH, Max + length(H) + 1) of
+            Input = case (C == $s orelse C == $p) andalso lager_stdlib:string_p(AH) of
+                true ->
+                    lists:flatten(AH);
+                _ -> AH
+            end,
+            case print(Input, Max + length(H) + 1) of
                 {_Res, Max} ->
                     % this isn't the last argument, but it consumed all available space
                     % delay calculating the print size until the end
-                    format(T, AT, Max + length(H) + 1, ["~s" | Acc], [{future, AH} | ArgAcc]);
+                    format(T, AT, Max + length(H) + 1, ["~s" | Acc], [{future, Input} | ArgAcc]);
                 {String, Length} ->
-                    {Value, RealLen} = case H of
-                        "s" ->
+                    {Value, RealLen} = case C of
+                        $s ->
                             % strip off the doublequotes
                             {string:substr(String, 2, length(String) -2), Length -2};
                         _ ->
@@ -124,11 +143,16 @@ format([[$~|H]| T], [AH | AT], Max, Acc, ArgAcc) ->
             %% safely at the moment, so just treat it like a regular ~p
             %% TODO support for depth limiting
             [_ | AT2] = AT,
-            case print(AH, Max + 2) of
+            Input = case C == $P andalso lager_stdlib:string_p(AH) of
+                true ->
+                    lists:flatten(AH);
+                _ -> AH
+            end,
+            case print(Input, Max + 2) of
                 {_Res, Max} ->
                     % this isn't the last argument, but it consumed all available space
                     % delay calculating the print size until the end
-                    format(T, AT2, Max + 2, ["~s" | Acc], [{future, AH} | ArgAcc]);
+                    format(T, AT2, Max + 2, ["~s" | Acc], [{future, Input} | ArgAcc]);
                 {String, Length} ->
                     format(T, AT2, Max + 2 - Length, ["~s" | Acc], [String | ArgAcc])
             end;
@@ -296,6 +320,7 @@ alist(L, Max) ->
     {[$", $[, R, $]], Len + 3}.
 
 
+-ifdef(TEST).
 %%--------------------
 %% The start of a test suite. So far, it only checks for not crashing.
 -spec test() -> ok.
@@ -352,3 +377,19 @@ perf1() ->
     {N, _} = timer:tc(trunc_io, print, [A, 1500]),
     {M, _} = timer:tc(io_lib, write, [A]),
     {N, M}.
+
+format_test() ->
+    %% simple format strings
+    ?assertEqual("foobar", lists:flatten(format("~s", [["foo", $b, $a, $r]], 50))),
+    ?assertEqual("\"foobar\"", lists:flatten(format("~p", [["foo", $b, $a, $r]], 50))),
+    ?assertEqual("\"foobar\"", lists:flatten(format("~P", [["foo", $b, $a, $r], 10], 50))),
+    ?assertEqual("[\"foo\",98,97,114]", lists:flatten(format("~w", [["foo", $b, $a, $r], 10], 50))),
+    
+    %% complex ones
+    ?assertEqual("foobar", lists:flatten(format("~10s", [["foo", $b, $a, $r]], 50))),
+    ?assertEqual("\"foobar\"", lists:flatten(format("~10p", [["foo", $b, $a, $r]], 50))),
+    ?assertEqual("\"foobar\"", lists:flatten(format("~10P", [["foo", $b, $a, $r], 10], 50))),
+    ?assertEqual("[\"foo\",98,97,114]", lists:flatten(format("~10W", [["foo", $b, $a, $r], 10], 50))),
+    ok.
+
+-endif.

test/lager_crash_backend.erl

@@ -0,0 +1,68 @@
+%% 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_backend).
+
+-include("lager.hrl").
+
+-behaviour(gen_event).
+
+-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
+        code_change/3]).
+
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-endif.
+
+init([CrashBefore, CrashAfter]) ->
+    case is_tuple(CrashBefore) andalso (timer:now_diff(CrashBefore, os:timestamp()) > 0) of
+        true ->
+            %?debugFmt("crashing!~n", []),
+            {error, crashed};
+        _ ->
+            %?debugFmt("Not crashing!~n", []),
+            case is_tuple(CrashAfter) of
+                true ->
+                    CrashTime = timer:now_diff(CrashAfter, os:timestamp()) div 1000,
+                    case CrashTime > 0 of
+                        true ->
+                            %?debugFmt("crashing in ~p~n", [CrashTime]),
+                            erlang:send_after(CrashTime, self(), crash),
+                            {ok, {}};
+                        _ -> {error, crashed}
+                    end;
+                _ ->
+                    {ok, {}}
+            end
+    end.
+
+handle_call(_Request, State) ->
+    {ok, ok, State}.
+
+handle_event(_Event, State) ->
+    {ok, State}.
+
+handle_info(crash, _State) ->
+    %?debugFmt("Time to crash!~n", []),
+    crash;
+handle_info(_Info, State) ->
+    {ok, State}.
+
+terminate(_Reason, _State) ->
+    ok.
+
+code_change(_OldVsn, State, _Extra) ->
+    {ok, State}.

test/lager_test_backend.erl

@@ -28,6 +28,7 @@
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
+-export([pop/0, count/0, count_ignored/0, flush/0]).
 -endif.
 
 init(Level) ->
@@ -81,6 +82,9 @@ count() ->
 count_ignored() ->
     gen_event:call(lager_event, ?MODULE, count_ignored).
 
+flush() ->
+    gen_event:call(lager_event, ?MODULE, flush).
+
 not_running_test() ->
     ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).