Tests for the crash log

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("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("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("test.log", 65535),
+                        error_logger:error_msg("Test message\n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("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("test.log"),
+                        file:write_file_info("test.log", FInfo#file_info{mode = 0}),
+                        {ok, _} = ?MODULE:start_link("test.log", 65535),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open crash log file 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("test.log", 65535),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        error_logger:error_msg("Test message\n"),
+                        timer:sleep(100),
+                        ?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}),
+                        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 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}),
+                        {ok, _} = ?MODULE:start_link("test.log", 65535),
+                        ?assertEqual(1, lager_test_backend:count()),
+                        {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(),
+                        ?assertEqual("Failed to open crash log file test.log with error: permission denied", lists:flatten(Message)),
+                        file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}),
+                        error_logger:error_msg("Test message~n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("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("test.log", 65535),
+                        ?assertEqual(0, lager_test_backend:count()),
+                        error_logger:error_msg("Test message~n"),
+                        timer:sleep(100),
+                        {ok, Bin} = file:read_file("test.log"),
+                        ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])),
+                        file:delete("test.log"),
+                        file:write_file("test.log", ""),
+                        error_logger:error_msg("Test message1~n"),
+                        timer:sleep(100),
+                        {ok, Bin1} = file:read_file("test.log"),
+                        ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])),
+                        file:rename("test.log", "test.log.0"),
+                        error_logger:error_msg("Test message2~n"),
+                        timer:sleep(100),
+                        {ok, Bin2} = file:read_file("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]).
@@ -323,32 +322,32 @@ filesystem_test_() ->
                 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"),
+                        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 message"),
+                        lager:log(error, self(), "Test message2"),
                         {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}])),
+                        ?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 message"),
+                        lager:log(error, self(), "Test message3"),
                         {ok, Bin2} = file:read_file("test.log"),
-                        ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}]))
+                        ?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 message"),
-                        lager:log(error, self(), "Test message"),
+                        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 message"), %% this won't get logged
-                        lager:log(error, self(), "Test message"),
+                        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)

test/lager_test_backend.erl

@@ -28,7 +28,7 @@
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
--export([pop/0, count/0, count_ignored/0]).
+-export([pop/0, count/0, count_ignored/0, flush/0]).
 -endif.
 
 init(Level) ->
@@ -82,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")).