From 35115d8f1f858a3217398554093517d81db309cb Mon Sep 17 00:00:00 2001 From: Csaba Hoch Date: Mon, 30 Jan 2017 19:21:51 +0100 Subject: [PATCH] Fix path expansion for traces when log_root is set Previously the following configuration didn't work properly: {log_root, "logs"}, {handlers, [{lager_file_backend, [{file, "access.log"}, {level, none}, ...]}]}, {traces, [{{lager_file_backend, "access.log"}, [{tag, access}], info}]} When lager:trace_file was trying to find a file among the existing handlers, it was searching for the expanded file name ("logs/access.log"), but the handlers store the file names without expansion ("access.log"), so it didn't find it. The result was that lager:trace_file started another "access.log" backend, which of course didn't use e.g. the log rotation settings of the first handler. When the log_root was relative, then each log message appeared twice in the log file (both backends thought that they should log it, because when calculating the Destination, "logs/access.log" was used in both cases). Now the code performs path expansion on the file name inside the handler too. Also, now it calculates the absolute paths of both files, so that if one file is specified with an absolute path and the other with a relative path, lager will still know that they are the same. Test ---- Using the old code (tag 3.2.4 was tested) the new test usually fails the following way: module 'lager_trace_test' lager_trace_test: trace_test_ (Trace combined with log_root)...*failed* in function lager_trace_test:'-trace_test_/0-fun-6-'/0 (test/lager_trace_test.erl, line 71) **throw:{too_many_entries,{ok,<<"Test message\n2017-03-26 23:04:23.935 [info] <0.5898.0>@lager"...>>}} output:<<"">> The reason for failing only usually is that it might happen that the duplicate log entry is added to file only after we called time:sleep(1000) and checked that the log entry is not there. --- src/lager.erl | 2 +- src/lager_util.erl | 22 +++++++- test/lager_trace_test.erl | 103 ++++++++++++++++++++++++++++++++++++++ 3 files changed, 125 insertions(+), 2 deletions(-) create mode 100644 test/lager_trace_test.erl 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.