From d828c35f12532b52701cb66f2ff20a6c37716b18 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Fri, 12 Aug 2011 16:13:13 -0400 Subject: [PATCH] Fixup the tests after merging in the rotation code --- include/lager.hrl | 10 ++++++ src/lager_console_backend.erl | 4 +-- src/lager_crash_log.erl | 54 ++++++++++++++-------------- src/lager_file_backend.erl | 13 +++++-- src/lager_handler_watcher.erl | 50 ++++++++++++++------------ test/lager_crash_backend.erl | 68 +++++++++++++++++++++++++++++++++++ 6 files changed, 146 insertions(+), 53 deletions(-) create mode 100644 test/lager_crash_backend.erl diff --git a/include/lager.hrl b/include/lager.hrl index 5ac5f67..56d13ad 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -63,6 +63,15 @@ %% 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 -> + ?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 @@ -83,3 +92,4 @@ end end end)). +-endif. diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index ace74cb..e59870f 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -99,7 +99,7 @@ console_log_test_() -> end, fun(_) -> application:stop(lager), - application:load(lager), + application:unload(lager), error_logger:tty(true) end, [ @@ -150,7 +150,7 @@ set_loglevel_test_() -> end, fun(_) -> application:stop(lager), - application:load(lager), + application:unload(lager), error_logger:tty(true) end, [ diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index f04d50a..81e553d 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -226,7 +226,7 @@ sasl_limited_str(crash_report, Report, FmtMaxBytes) -> filesystem_test_() -> {foreach, fun() -> - file:write_file("test.log", ""), + file:write_file("crash_test.log", ""), error_logger:tty(false), application:load(lager), application:set_env(lager, handlers, [{lager_test_backend, info}]), @@ -242,7 +242,7 @@ filesystem_test_() -> exit(P, kill); _ -> ok end, - file:delete("test.log"), + file:delete("crash_test.log"), application:stop(lager), application:unload(lager), error_logger:tty(true) @@ -250,77 +250,77 @@ filesystem_test_() -> [ {"under normal circumstances, file should be opened", fun() -> - {ok, _} = ?MODULE:start_link("test.log", 65535), + {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("test.log"), + {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("test.log"), - file:write_file_info("test.log", FInfo#file_info{mode = 0}), - {ok, _} = ?MODULE:start_link("test.log", 65535), + {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 test.log with error: permission denied", lists:flatten(Message)) + ?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("test.log", 65535), + {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("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}), + 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 test.log with error: permission denied", lists:flatten(Message)) + ?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("test.log"), + {ok, FInfo} = file:read_file_info("crash_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), + 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 test.log with error: permission denied", lists:flatten(Message)), - file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}), + ?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("test.log"), + {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("test.log", 65535), + {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("test.log"), + {ok, Bin} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - file:delete("test.log"), - file:write_file("test.log", ""), + 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("test.log"), + {ok, Bin1} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), - file:rename("test.log", "test.log.0"), + file:rename("crash_test.log", "crash_test.log.0"), error_logger:error_msg("Test message2~n"), timer:sleep(100), - {ok, Bin2} = file:read_file("test.log"), + {ok, Bin2} = file:read_file("crash_test.log"), ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) end } diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index e4206cb..b685b44 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -167,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 @@ -175,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), @@ -208,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) -> diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index b285a6d..8c60385 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -107,16 +107,19 @@ reinstall_on_initial_failure_test_() -> application:set_env(lager, error_logger_redirect, false), application:unset_env(lager, crash_log), application:start(lager), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), - ?assertEqual("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))), - application:stop(lager), - application:unload(lager), - error_logger:tty(true) + 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 ] }. @@ -131,18 +134,21 @@ reinstall_on_runtime_failure_test_() -> application:set_env(lager, error_logger_redirect, false), application:unset_env(lager, crash_log), application:start(lager), - ?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(), - ?assertEqual("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))), - application:stop(lager), - application:unload(lager), - error_logger:tty(true) + 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 ] }. diff --git a/test/lager_crash_backend.erl b/test/lager_crash_backend.erl new file mode 100644 index 0000000..b5981cb --- /dev/null +++ b/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}.