diff --git a/src/lager.erl b/src/lager.erl index d8d7792..705fa23 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -214,7 +214,7 @@ trace_file(File, Filter, Level, Options) -> {Sink, {ok, Trace}} -> Handlers = lager_config:global_get(handlers, []), %% check if this file backend is already installed - Res = case lists:keyfind({lager_file_backend, FileName}, 1, Handlers) of + Res = case lager_util:find_file(FileName, Handlers) of false -> %% install the handler LogFileConfig = diff --git a/src/lager_util.erl b/src/lager_util.erl index 842ef32..c33d1a9 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -28,7 +28,7 @@ open_logfile/2, ensure_logfile/4, rotate_logfile/2, format_time/0, format_time/1, localtime_ms/0, localtime_ms/1, maybe_utc/1, parse_rotation_date_spec/1, calculate_next_rotation/1, validate_trace/1, check_traces/4, is_loggable/3, - trace_filter/1, trace_filter/2, expand_path/1, check_hwm/1, + trace_filter/1, trace_filter/2, expand_path/1, find_file/2, check_hwm/1, make_internal_sink_name/1, otp_version/0 ]). @@ -514,6 +514,26 @@ expand_path(RelPath) -> RelPath end. +%% Find a file among the already installed handlers. +%% +%% The file is already expanded (i.e. lager_util:expand_path already added the +%% "log_root"), but the file paths inside Handlers are not. +find_file(_File1, _Handlers = []) -> + false; +find_file(File1, [{{lager_file_backend, File2}, _Handler, _Sink} = HandlerInfo | Handlers]) -> + File1Abs = filename:absname(File1), + File2Abs = filename:absname(lager_util:expand_path(File2)), + case File1Abs =:= File2Abs of + true -> + % The file inside HandlerInfo is the same as the file we are looking + % for, so we are done. + HandlerInfo; + false -> + find_file(File1, Handlers) + end; +find_file(File1, [_HandlerInfo | Handlers]) -> + find_file(File1, Handlers). + %% Log rate limit, i.e. high water mark for incoming messages check_hwm(Shaper = #lager_shaper{hwm = undefined}) -> diff --git a/test/lager_trace_test.erl b/test/lager_trace_test.erl new file mode 100644 index 0000000..48d722d --- /dev/null +++ b/test/lager_trace_test.erl @@ -0,0 +1,103 @@ +-module(lager_trace_test). + +-compile([{parse_transform, lager_transform}]). + +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). + +% Our expectation is that the first log entry will appear so we won't actually +% wait out ?FIRST_LOG_ENTRY_TIMEOUT. On the other hand, the second log entry is +% expected never to arrive, so the test will wait out ?SECOND_LOG_ENTRY_TIMEOUT; +% that's why it is shorter. +-define(FIRST_LOG_ENTRY_TIMEOUT, (10 * 1000)). % 10 seconds +-define(SECOND_LOG_ENTRY_TIMEOUT, 1000). % 1 second + +-define(FNAME, "test/test1.log"). + +trace_test_() -> + {timeout, + 10, + {foreach, + fun() -> + file:write_file(?FNAME, ""), + error_logger:tty(false), + application:load(lager), + application:set_env(lager, log_root, "test"), + application:set_env(lager, handlers, + [{lager_file_backend, + [{file, "test1.log"}, + {level, none}, + {formatter, lager_default_formatter}, + {formatter_config, [message, "\n"]} + ]}]), + application:set_env(lager, traces, + [{{lager_file_backend, "test1.log"}, + [{tag, mytag}], info}]), + application:set_env(lager, error_logger_redirect, false), + application:set_env(lager, async_threshold, undefined), + lager:start() + end, + fun(_) -> + file:delete(?FNAME), + application:stop(lager), + application:stop(goldrush), + application:unset_env(lager, log_root), + application:unset_env(lager, handlers), + application:unset_env(lager, traces), + application:unset_env(lager, error_logger_redirect), + application:unset_env(lager, async_threshold), + error_logger:tty(true) + end, + [{"Trace combined with log_root", + fun() -> + lager:info([{tag, mytag}], "Test message"), + + % Wait until we have the expected log entry in the log file. + case wait_until(fun() -> + count_lines(?FNAME) >= 1 + end, ?FIRST_LOG_ENTRY_TIMEOUT) of + ok -> + ok; + {error, timeout} -> + throw({file_empty, file:read_file(?FNAME)}) + end, + + % Let's wait a little to see that we don't get a duplicate log + % entry. + case wait_until(fun() -> + count_lines(?FNAME) >= 2 + end, ?SECOND_LOG_ENTRY_TIMEOUT) of + ok -> + throw({too_many_entries, file:read_file(?FNAME)}); + {error, timeout} -> + ok + end + end} + ]}}. + +% Wait until Fun() returns true. +wait_until(Fun, Timeout) -> + wait_until(Fun, Timeout, {8, 13}). + +wait_until(_Fun, Timeout, {T1, _}) when T1 > Timeout -> + {error, timeout}; +wait_until(Fun, Timeout, {T1, T2}) -> + case Fun() of + true -> + ok; + false -> + timer:sleep(T1), + wait_until(Fun, Timeout, {T2, T1 + T2}) + end. + +% Return the number of lines in a file. Return 0 for a non-existent file. +count_lines(Filename) -> + case file:read_file(Filename) of + {ok, Content} -> + Lines = binary:split(Content, <<"\n">>, [global, trim]), + length(Lines); + {error, _} -> + 0 + end. + +-endif.