From d78c207cffb04bc5c72c30714600c55a9acbf1f3 Mon Sep 17 00:00:00 2001 From: Ali Sabil Date: Thu, 30 Jan 2014 16:34:42 +0100 Subject: [PATCH 001/102] Add support for handling ranch errors --- src/error_logger_lager_h.erl | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 1c7e092..078b60c 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -178,6 +178,19 @@ log_event(Event, State) -> "Cowboy handler ~p terminated in ~p:~p/~p with reason: ~s", [Module, Module, Function, Arity, format_reason({Reason, StackTrace})]) end; + "Ranch listener "++_ -> + %% Ranch errors + ?CRASH_LOG(Event), + case Args of + [Ref, _Protocol, Worker, {[{reason, Reason}, {mfa, {Module, Function, Arity}}, {stacktrace, StackTrace} | _], _}] -> + ?LOGFMT(error, Worker, + "Ranch listener ~p terminated in ~p:~p/~p with reason: ~s", + [Ref, Module, Function, Arity, format_reason({Reason, StackTrace})]); + [Ref, _Protocol, Worker, Reason] -> + ?LOGFMT(error, Worker, + "Ranch listener ~p terminated with reason: ~s", + [Ref, format_reason(Reason)]) + end; "webmachine error"++_ -> %% Webmachine HTTP server error ?CRASH_LOG(Event), From e1a2907d5c2fdc8b2d938c67a391673a478ee38b Mon Sep 17 00:00:00 2001 From: Eric Liang Date: Tue, 20 Jan 2015 00:52:14 +0800 Subject: [PATCH 002/102] refactor message flow control by encapsulating high water mark in lager_shaper --- include/lager.hrl | 12 ++++++ src/error_logger_lager_h.erl | 82 +++++++++--------------------------- src/lager.erl | 1 + src/lager_util.erl | 42 +++++++++++++++++- 4 files changed, 73 insertions(+), 64 deletions(-) diff --git a/include/lager.hrl b/include/lager.hrl index ade93e1..bace15f 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -100,3 +100,15 @@ end)). -endif. +-record(lager_shaper, { + %% how many messages per second we try to deliver + hwm = undefined :: 'undefined' | pos_integer(), + %% how many messages we've received this second + mps = 0 :: non_neg_integer(), + %% the current second + lasttime = os:timestamp() :: erlang:timestamp(), + %% count of dropped messages this second + dropped = 0 :: non_neg_integer() + }). + +-type lager_shaper() :: #lager_shaper{}. diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 321afc7..0aa3b30 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -33,16 +33,7 @@ -export([format_reason/1]). --record(state, { - %% how many messages per second we try to deliver - hwm = undefined :: 'undefined' | pos_integer(), - %% how many messages we've received this second - mps = 0 :: non_neg_integer(), - %% the current second - lasttime = os:timestamp() :: erlang:timestamp(), - %% count of dropped messages this second - dropped = 0 :: non_neg_integer() - }). +-record(state, { shaper :: lager_shaper() }). -define(LOGMSG(Level, Pid, Msg), case ?SHOULD_LOG(Level) of @@ -75,19 +66,28 @@ set_high_water(N) -> -spec init(any()) -> {ok, #state{}}. init([HighWaterMark]) -> - {ok, #state{hwm=HighWaterMark}}. + Shaper = #lager_shaper{hwm=HighWaterMark}, + {ok, #state{shaper=Shaper}}. -handle_call({set_high_water, N}, State) -> - {ok, ok, State#state{hwm = N}}; +handle_call({set_high_water, N}, #state{shaper=Shaper} = State) -> + NewShaper = Shaper#lager_shaper{hwm=N}, + {ok, ok, State#state{shaper = NewShaper}}; handle_call(_Request, State) -> {ok, unknown_call, State}. -handle_event(Event, State) -> - case check_hwm(State) of - {true, NewState} -> - log_event(Event, NewState); - {false, NewState} -> - {ok, NewState} +handle_event(Event, #state{shaper=Shaper} = State) -> + case lager_util:check_hwm(Shaper) of + {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} -> + case Drop > 0 of + true -> + ?LOGFMT(warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", + [Drop, Hwm]); + false -> + ok + end, + log_event(Event, State#state{shaper=NewShaper}); + {false, _, NewShaper} -> + {ok, State#state{shaper=NewShaper}} end. handle_info(_Info, State) -> @@ -101,50 +101,6 @@ code_change(_OldVsn, State, _Extra) -> %% internal functions -check_hwm(State = #state{hwm = undefined}) -> - {true, State}; -check_hwm(State = #state{mps = Mps, hwm = Hwm}) when Mps < Hwm -> - %% haven't hit high water mark yet, just log it - {true, State#state{mps=Mps+1}}; -check_hwm(State = #state{hwm = Hwm, lasttime = Last, dropped = Drop}) -> - %% are we still in the same second? - {M, S, _} = Now = os:timestamp(), - case Last of - {M, S, _} -> - %% still in same second, but have exceeded the high water mark - NewDrops = discard_messages(Now, 0), - {false, State#state{dropped=Drop+NewDrops}}; - _ -> - %% different second, reset all counters and allow it - case Drop > 0 of - true -> - ?LOGFMT(warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", - [Drop, Hwm]); - false -> - ok - end, - {true, State#state{dropped = 0, mps=1, lasttime = Now}} - end. - -discard_messages(Second, Count) -> - {M, S, _} = os:timestamp(), - case Second of - {M, S, _} -> - receive - %% we only discard gen_event notifications, because - %% otherwise we might discard gen_event internal - %% messages, such as trapped EXITs - {notify, _Event} -> - discard_messages(Second, Count+1); - {_From, _Tag, {sync_notify, _Event}} -> - discard_messages(Second, Count+1) - after 0 -> - Count - end; - _ -> - Count - end. - log_event(Event, State) -> case Event of {error, _GL, {Pid, Fmt, Args}} -> diff --git a/src/lager.erl b/src/lager.erl index aa2ac24..1d5f3fa 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -413,3 +413,4 @@ is_record_known(Record, Module) -> end end end. + diff --git a/src/lager_util.erl b/src/lager_util.erl index 67894ff..2e76d2c 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -22,7 +22,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]). + trace_filter/1, trace_filter/2, check_hwm/1]). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -467,6 +467,46 @@ i2l(I) -> integer_to_list(I). i3l(I) when I < 100 -> [$0 | i2l(I)]; i3l(I) -> integer_to_list(I). +%% Log rate limit, i.e. high water mark for incoming messages + +check_hwm(Shaper = #lager_shaper{hwm = undefined}) -> + {true, 0, Shaper}; +check_hwm(Shaper = #lager_shaper{mps = Mps, hwm = Hwm}) when Mps < Hwm -> + %% haven't hit high water mark yet, just log it + {true, 0, Shaper#lager_shaper{mps=Mps+1}}; +check_hwm(Shaper = #lager_shaper{lasttime = Last, dropped = Drop}) -> + %% are we still in the same second? + {M, S, _} = Now = os:timestamp(), + case Last of + {M, S, _} -> + %% still in same second, but have exceeded the high water mark + NewDrops = discard_messages(Now, 0), + {false, 0, Shaper#lager_shaper{dropped=Drop+NewDrops}}; + _ -> + %% different second, reset all counters and allow it + {true, Drop, Shaper#lager_shaper{dropped = 0, mps=1, lasttime = Now}} + end. + +discard_messages(Second, Count) -> + {M, S, _} = os:timestamp(), + case Second of + {M, S, _} -> + receive + %% we only discard gen_event notifications, because + %% otherwise we might discard gen_event internal + %% messages, such as trapped EXITs + {notify, _Event} -> + discard_messages(Second, Count+1); + {_From, _Tag, {sync_notify, _Event}} -> + discard_messages(Second, Count+1) + after 0 -> + Count + end; + _ -> + Count + end. + + -ifdef(TEST). parse_test() -> From 1be7d7378f03810e6d7f4950f7e603bc11b144a1 Mon Sep 17 00:00:00 2001 From: Eric Liang Date: Tue, 20 Jan 2015 00:53:01 +0800 Subject: [PATCH 003/102] add high water mark support to lager_file_backend --- src/lager_file_backend.erl | 46 +++++++++++++++++++++++++++++++++----- 1 file changed, 40 insertions(+), 6 deletions(-) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 5c761a8..8fbcc5c 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -63,6 +63,7 @@ size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), + shaper :: lager_shaper(), formatter :: atom(), formatter_config :: any(), sync_on :: {'mask', integer()}, @@ -74,7 +75,8 @@ -type option() :: {file, string()} | {level, lager:log_level()} | {size, non_neg_integer()} | {date, string()} | - {count, non_neg_integer()} | {sync_interval, non_neg_integer()} | + {count, non_neg_integer()} | {high_water_mark, non_neg_integer()} | + {sync_interval, non_neg_integer()} | {sync_size, non_neg_integer()} | {sync_on, lager:log_level()} | {check_interval, non_neg_integer()} | {formatter, atom()} | {formatter_config, term()}. @@ -102,10 +104,11 @@ init(LogFileConfig) when is_list(LogFileConfig) -> {error, {fatal, bad_config}}; Config -> %% probabably a better way to do this, but whatever - [Name, Level, Date, Size, Count, SyncInterval, SyncSize, SyncOn, CheckInterval, Formatter, FormatterConfig] = - [proplists:get_value(Key, Config) || Key <- [file, level, date, size, count, sync_interval, sync_size, sync_on, check_interval, formatter, formatter_config]], + [Name, Level, Date, Size, Count, HighWaterMark, SyncInterval, SyncSize, SyncOn, CheckInterval, Formatter, FormatterConfig] = + [proplists:get_value(Key, Config) || Key <- [file, level, date, size, count, high_water_mark, sync_interval, sync_size, sync_on, check_interval, formatter, formatter_config]], schedule_rotation(Name, Date), - State0 = #state{name=Name, level=Level, size=Size, date=Date, count=Count, formatter=Formatter, + Shaper = #lager_shaper{hwm=HighWaterMark}, + State0 = #state{name=Name, level=Level, size=Size, date=Date, count=Count, shaper=Shaper, formatter=Formatter, formatter_config=FormatterConfig, sync_on=SyncOn, sync_interval=SyncInterval, sync_size=SyncSize, check_interval=CheckInterval}, State = case lager_util:open_logfile(Name, {SyncSize, SyncInterval}) of @@ -134,10 +137,30 @@ handle_call(_Request, State) -> %% @private handle_event({log, Message}, - #state{name=Name, level=L,formatter=Formatter,formatter_config=FormatConfig} = State) -> + #state{name=Name, level=L, shaper=Shaper, + formatter=Formatter,formatter_config=FormatConfig} = State) -> case lager_util:is_loggable(Message,L,{lager_file_backend, Name}) of true -> - {ok,write(State, lager_msg:timestamp(Message), lager_msg:severity_as_int(Message), Formatter:format(Message,FormatConfig)) }; + case lager_util:check_hwm(Shaper) of + {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} -> + NewState = case Drop > 0 of + true -> + Report = io_lib:format("lager_file_backend dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, Hwm]), + ReportMsg = lager_msg:new(Report, warning, [], []), + write(State, + lager_msg:timestamp(ReportMsg), + lager_msg:severity_as_int(ReportMsg), + Formatter:format(ReportMsg, FormatConfig)); + false -> + State + end, + {ok,write(NewState#state{shaper=NewShaper}, + lager_msg:timestamp(Message), + lager_msg:severity_as_int(Message), + Formatter:format(Message,FormatConfig)) }; + {false, _, NewShaper} -> + {ok, State#state{shaper=NewShaper}} + end; false -> {ok, State} end; @@ -300,6 +323,13 @@ validate_logfile_proplist([{count, Count}|Tail], Acc) -> _ -> throw({bad_config, "Invalid rotation count", Count}) end; +validate_logfile_proplist([{high_water_mark, HighWaterMark}|Tail], Acc) -> + case HighWaterMark of + Hwm when is_integer(Hwm), Hwm >= 0 -> + validate_logfile_proplist(Tail, [{high_water_mark, Hwm}|Acc]); + _ -> + throw({bad_config, "Invalid high water mark", HighWaterMark}) + end; validate_logfile_proplist([{date, Date}|Tail], Acc) -> case lager_util:parse_rotation_date_spec(Date) of {ok, Spec} -> @@ -768,6 +798,10 @@ config_validation_test_() -> ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {count, infinity}])) }, + {"bad high water mark", + ?_assertEqual(false, + validate_logfile_proplist([{file, "test.log"}, {high_water_mark, infinity}])) + }, {"bad date", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {date, "midnight"}])) From cd36e96fd7ecdaaca9e9bc5709d6f8daa6c079c5 Mon Sep 17 00:00:00 2001 From: Eric Liang Date: Tue, 20 Jan 2015 17:36:56 +0800 Subject: [PATCH 004/102] add set_loghwm method in order to change high water mark on the fly --- src/lager.erl | 10 +++++++++- src/lager_file_backend.erl | 9 +++++++++ 2 files changed, 18 insertions(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index 1d5f3fa..be1d8ba 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -29,7 +29,7 @@ trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, clear_all_traces/0, stop_trace/1, status/0, get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, - update_loglevel_config/0, posix_error/1, + update_loglevel_config/0, posix_error/1, set_loghwm/2, set_loghwm/3, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/9, do_log/9, pr/2]). @@ -320,6 +320,14 @@ get_loglevels() -> [gen_event:call(lager_event, Handler, get_loglevel, infinity) || Handler <- gen_event:which_handlers(lager_event)]. +%% @doc Set the loghwm for a particular backend. +set_loghwm(Handler, Hwm) when is_integer(Hwm) -> + gen_event:call(lager_event, Handler, {set_loghwm, Hwm}, infinity). + +%% @doc Set the loghwm (log high water mark) for file backends with multiple identifiers +set_loghwm(Handler, Ident, Hwm) when is_integer(Hwm) -> + gen_event:call(lager_event, {Handler, Ident}, {set_loghwm, Hwm}, infinity). + %% @private add_trace_to_loglevel_config(Trace) -> {MinLevel, Traces} = lager_config:get(loglevel), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 8fbcc5c..c19f69a 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -132,6 +132,15 @@ handle_call({set_loglevel, Level}, #state{name=Ident} = State) -> end; handle_call(get_loglevel, #state{level=Level} = State) -> {ok, Level, State}; +handle_call({set_loghwm, Hwm}, #state{shaper=Shaper, name=Name} = State) -> + case validate_logfile_proplist([{file, Name}, {high_water_mark, Hwm}]) of + false -> + {ok, {error, bad_log_hwm}, State}; + _ -> + NewShaper = Shaper#lager_shaper{hwm=Hwm}, + ?INT_LOG(notice, "Changed loghwm of ~s to ~p", [Name, Hwm]), + {ok, {last_loghwm, Shaper#lager_shaper.hwm}, State#state{shaper=NewShaper}} + end; handle_call(_Request, State) -> {ok, ok, State}. From 55fba1e3ba2188bb6f0aeb6bf509c2b31888f588 Mon Sep 17 00:00:00 2001 From: Eric Liang Date: Fri, 23 Jan 2015 01:52:53 +0800 Subject: [PATCH 005/102] don't discard notify message which will hang a caller waiting for the response forever --- src/lager_util.erl | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/lager_util.erl b/src/lager_util.erl index 2e76d2c..55edd65 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -496,8 +496,6 @@ discard_messages(Second, Count) -> %% otherwise we might discard gen_event internal %% messages, such as trapped EXITs {notify, _Event} -> - discard_messages(Second, Count+1); - {_From, _Tag, {sync_notify, _Event}} -> discard_messages(Second, Count+1) after 0 -> Count From 546036f75a3a20be7a5830caf8ad986238782500 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Thu, 5 Mar 2015 17:03:18 -0600 Subject: [PATCH 006/102] WIP First pass at adding sink parameter into the external API layer. TODO: * config updates * loglevel changes per sink --- src/lager.erl | 55 ++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 44 insertions(+), 11 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index cfae17d..2e44aff 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -24,7 +24,7 @@ %% API -export([start/0, - log/3, log/4, + log/3, log/4, log/5, md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, @@ -81,11 +81,15 @@ md(NewMD) when is_list(NewMD) -> md(_) -> erlang:error(badarg). --spec dispatch_log(log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running}. -%% this is the same check that the parse transform bakes into the module at compile time + dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> + dispatch_log(lager_event, Severity, Metadata, Format, Args, Size). + +-spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running}. +%% this is the same check that the parse transform bakes into the module at compile time +dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> SeverityAsInt=lager_util:level_to_num(Severity), - case {whereis(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of + case {whereis(Sink), lager_config:get(Sink, loglevel, {?LOG_NONE, []})} of {undefined, _} -> {error, lager_not_running}; {Pid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> @@ -126,6 +130,11 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, Size) -> dispatch_log(Severity, Metadata, Format, Args, Size). + +%% TODO: +%% Consider making log2/4 that takes the Level, Pid and Message params of log/3 +%% along with a Sink param?? + %% @doc Manually log a message into lager without using the parse transform. -spec log(log_level(), pid() | atom() | [tuple(),...], list()) -> ok | {error, lager_not_running}. log(Level, Pid, Message) when is_pid(Pid); is_atom(Pid) -> @@ -140,6 +149,13 @@ log(Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> log(Level, Metadata, Format, Args) when is_list(Metadata) -> dispatch_log(Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION). +%% @doc Manually log a message into lager without using the parse transform. +-spec log(atom(), log_level(), pid() | atom() | [tuple(),...], string(), list()) -> ok | {error, lager_not_running}. +log(Sink, Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> + dispatch_log(Sink, Level, [{pid,Pid}], Format, Args, ?DEFAULT_TRUNCATION); +log(Sink, Level, Metadata, Format, Args) when is_list(Metadata) -> + dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION). + trace_file(File, Filter) -> trace_file(File, Filter, debug, []). @@ -149,6 +165,10 @@ trace_file(File, Filter, Level) when is_atom(Level) -> trace_file(File, Filter, Options) when is_list(Options) -> trace_file(File, Filter, debug, Options). +%% FIXME: All of this code assumes a single event handler +%% In fact anywhere there's `lager_event' assume that the code +%% should be generalized to support multiple sinks. + trace_file(File, Filter, Level, Options) -> Trace0 = {Filter, Level, {lager_file_backend, File}}, case lager_util:validate_trace(Trace0) of @@ -294,21 +314,34 @@ status() -> %% @doc Set the loglevel for a particular backend. set_loglevel(Handler, Level) when is_atom(Level) -> - Reply = gen_event:call(lager_event, Handler, {set_loglevel, Level}, infinity), - update_loglevel_config(), - Reply. + set_loglevel(lager_event, Handler, undefined, Level). %% @doc Set the loglevel for a particular backend that has multiple identifiers %% (eg. the file backend). set_loglevel(Handler, Ident, Level) when is_atom(Level) -> - Reply = gen_event:call(lager_event, {Handler, Ident}, {set_loglevel, Level}, infinity), + set_loglevel(lager_event, Handler, Ident, Level). + +%% @doc Set the loglevel for a particular sink's backend that potentially has +%% multiple identifiers. (Use `undefined' if it doesn't have any.) +set_loglevel(Sink, Handler, Ident, Level) when is_atom(Level) -> + HandlerArg = case Ident of + undefined -> Handler; + _ -> {Handler, Ident} + end, + Reply = gen_event:call(Sink, HandlerArg, {set_loglevel, Level}, infinity), update_loglevel_config(), Reply. -%% @doc Get the loglevel for a particular backend. In the case that the backend -%% has multiple identifiers, the lowest is returned + +%% @doc Get the loglevel for a particular backend on the default sink. In the case that the backend +%% has multiple identifiers, the lowest is returned. get_loglevel(Handler) -> - case gen_event:call(lager_event, Handler, get_loglevel, infinity) of + get_loglevel(lager_event, Handler). + +%% @doc Get the loglevel for a particular sink's backend. In the case that the backend +%% has multiple identifiers, the lowest is returned. +get_loglevel(Sink, Handler) -> + case gen_event:call(Sink, Handler, get_loglevel, infinity) of {mask, Mask} -> case lager_util:mask_to_levels(Mask) of [] -> none; From 90ce2ac2b90347d300b1e1beae65439535943ca3 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Thu, 5 Mar 2015 22:31:10 -0600 Subject: [PATCH 007/102] WIP Finish lager API modifications Update config API to handle multiple sinks Identify areas where new code is yet to be written --- src/lager.erl | 24 ++++++++++++------------ src/lager_app.erl | 3 +++ src/lager_config.erl | 33 ++++++++++++++++++++------------- src/lager_sup.erl | 5 +++++ 4 files changed, 40 insertions(+), 25 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 2e44aff..6f64813 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -28,9 +28,9 @@ md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, - get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, - update_loglevel_config/0, posix_error/1, - safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/9, + get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/1, + update_loglevel_config/1, posix_error/1, + safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, do_log/9, pr/2]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. @@ -329,7 +329,7 @@ set_loglevel(Sink, Handler, Ident, Level) when is_atom(Level) -> _ -> {Handler, Ident} end, Reply = gen_event:call(Sink, HandlerArg, {set_loglevel, Level}, infinity), - update_loglevel_config(), + update_loglevel_config(Sink), Reply. @@ -363,9 +363,9 @@ posix_error(Error) -> safe_format_chop("~p", [Error], ?DEFAULT_TRUNCATION). %% @private -get_loglevels() -> - [gen_event:call(lager_event, Handler, get_loglevel, infinity) || - Handler <- gen_event:which_handlers(lager_event)]. +get_loglevels(Sink) -> + [gen_event:call(Handler, get_loglevel, infinity) || + Handler <- gen_event:which_handlers(Sink)]. %% @private add_trace_to_loglevel_config(Trace) -> @@ -374,16 +374,16 @@ add_trace_to_loglevel_config(Trace) -> false -> NewTraces = [Trace|Traces], _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces]), - lager_config:set(loglevel, {MinLevel, [Trace|Traces]}); + lager_config:set(lager_event, loglevel, {MinLevel, [Trace|Traces]}); _ -> ok end. %% @doc recalculate min log level -update_loglevel_config() -> - {_, Traces} = lager_config:get(loglevel), - MinLog = minimum_loglevel(get_loglevels()), - lager_config:set(loglevel, {MinLog, Traces}). +update_loglevel_config(Sink) -> + {_, Traces} = lager_config:get(Sink, loglevel), + MinLog = minimum_loglevel(get_loglevels(Sink)), + lager_config:set(Sink, loglevel, {MinLog, Traces}). %% @private minimum_loglevel(Levels) -> diff --git a/src/lager_app.erl b/src/lager_app.erl index 6364aef..ace1a50 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -62,6 +62,9 @@ start(_StartType, _StartArgs) -> throw({error, bad_config}) end, + %% TODO: + %% Read config for other event sinks here and start them appropriately + Handlers = case application:get_env(lager, handlers) of undefined -> [{lager_console_backend, info}, diff --git a/src/lager_config.erl b/src/lager_config.erl index 17b4140..98b18cf 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -20,10 +20,15 @@ -include("lager.hrl"). --export([new/0, get/1, get/2, set/2]). +-export([new/0, get/1, get/2, get/3, set/2, set/3]). -define(TBL, lager_config). +%% For multiple sinks, the key is now the registered event name and the old key +%% as a tuple. +%% +%% {{lager_event, loglevel}, Value} instead of {loglevel, Value} + new() -> %% set up the ETS configuration table _ = try ets:new(?TBL, [named_table, public, set, {keypos, 1}, {read_concurrency, true}]) of @@ -36,29 +41,31 @@ new() -> %% use insert_new here so that if we're in an appup we don't mess anything up %% %% until lager is completely started, allow all messages to go through - ets:insert_new(?TBL, {loglevel, {element(2, lager_util:config_to_mask(debug)), []}}), + ets:insert_new(?TBL, {{lager_event, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}}), ok. - get(Key) -> - case ets:lookup(?TBL, Key) of - [] -> - undefined; - [{Key, Res}] -> - Res - end. + get(lager_event, Key, undefined). get(Key, Default) -> - try ?MODULE:get(Key) of - undefined -> + get(lager_event, Key, Default). + +get(Sink, Key, Default) -> + try + case ets:lookup(?TBL, {Sink, Key}) of + [] -> Default; - Res -> + [{{Sink, Key}, Res}] -> Res + end catch _:_ -> Default end. set(Key, Value) -> - ets:insert(?TBL, {Key, Value}). + set(lager_event, Key, Value). + +set(Sink, Key, Value) -> + ets:insert(?TBL, {{Sink, Key}, Value}). diff --git a/src/lager_sup.erl b/src/lager_sup.erl index c43bfd7..789fede 100644 --- a/src/lager_sup.erl +++ b/src/lager_sup.erl @@ -34,6 +34,11 @@ start_link() -> init([]) -> %% set up the config, is safe even during relups lager_config:new(), + %% TODO: + %% Always start lager_event as the default and make sure that + %% other gen_event stuff can start up as needed + %% + %% Maybe a new API to handle the sink and its policy? Children = [ {lager, {gen_event, start_link, [{local, lager_event}]}, permanent, 5000, worker, [dynamic]}, From f6e6b839275de2d4572ef672e3053c7a50cf8a7e Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 6 Mar 2015 14:43:42 -0600 Subject: [PATCH 008/102] Record some code comments from jrd walk-thru --- src/lager.app.src | 9 ++++++--- src/lager.erl | 2 +- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index e41da8e..e1ed54c 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -44,13 +44,16 @@ %% current one - default is 0 {crash_log_count, 5}, %% Whether to redirect error_logger messages into lager - defaults to true - {error_logger_redirect, true}, + {error_logger_redirect, lager_event}, %% <-- sink name %% How many messages per second to allow from error_logger before we start dropping them {error_logger_hwm, 50}, %% How big the gen_event mailbox can get before it is switched into sync mode - {async_threshold, 20}, + {async_threshold, 20}, %% <-- per sink %% Switch back to async mode, when gen_event mailbox size decrease from `async_threshold' %% to async_threshold - async_threshold_window - {async_threshold_window, 5} + {async_threshold_window, 5}, %% <-- per sink + {sinks, [ + {lager_event, [{async_threshold, 20}, {async_threshold_window, 5}]} + ]}, ]} ]}. diff --git a/src/lager.erl b/src/lager.erl index 6f64813..1fa2869 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -116,7 +116,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr end, LagerMsg = lager_msg:new(Msg, Severity, Metadata, Destinations), - case lager_config:get(async, false) of + case lager_config:get(Sink, async, false) of %% this needs to be able to get value from a non-default sink true -> gen_event:notify(Pid, {log, LagerMsg}); false -> From 730ab66717b617e8d53123b2b5955004b7a6175c Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Wed, 11 Mar 2015 16:55:38 -0400 Subject: [PATCH 009/102] For places in the revised API where we use lager_event as a default value, use a macro instead --- include/lager.hrl | 1 + src/lager.erl | 4 ++-- src/lager_config.erl | 7 +++---- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/include/lager.hrl b/include/lager.hrl index ade93e1..2f14b47 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -17,6 +17,7 @@ -define(DEFAULT_TRUNCATION, 4096). -define(DEFAULT_TRACER, lager_default_tracer). +-define(DEFAULT_SINK, lager_event). -define(LEVELS, [debug, info, notice, warning, error, critical, alert, emergency, none]). diff --git a/src/lager.erl b/src/lager.erl index 1fa2869..171c35b 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -83,7 +83,7 @@ md(_) -> dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> - dispatch_log(lager_event, Severity, Metadata, Format, Args, Size). + dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). -spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running}. %% this is the same check that the parse transform bakes into the module at compile time @@ -336,7 +336,7 @@ set_loglevel(Sink, Handler, Ident, Level) when is_atom(Level) -> %% @doc Get the loglevel for a particular backend on the default sink. In the case that the backend %% has multiple identifiers, the lowest is returned. get_loglevel(Handler) -> - get_loglevel(lager_event, Handler). + get_loglevel(?DEFAULT_SINK, Handler). %% @doc Get the loglevel for a particular sink's backend. In the case that the backend %% has multiple identifiers, the lowest is returned. diff --git a/src/lager_config.erl b/src/lager_config.erl index 98b18cf..263604c 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -45,10 +45,10 @@ new() -> ok. get(Key) -> - get(lager_event, Key, undefined). + get(?DEFAULT_SINK, Key, undefined). get(Key, Default) -> - get(lager_event, Key, Default). + get(?DEFAULT_SINK, Key, Default). get(Sink, Key, Default) -> try @@ -64,8 +64,7 @@ get(Sink, Key, Default) -> end. set(Key, Value) -> - set(lager_event, Key, Value). + set(?DEFAULT_SINK, Key, Value). set(Sink, Key, Value) -> ets:insert(?TBL, {{Sink, Key}, Value}). - From 2d33a134150e85b195529ce17446f225b881cf9d Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Thu, 12 Mar 2015 10:39:19 -0400 Subject: [PATCH 010/102] Clarify that "event" in this module is what we are now calling a "sink" --- src/lager_handler_watcher.erl | 34 +++++++++++++++++----------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index 24498a4..af0844d 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -38,18 +38,18 @@ -record(state, { module :: atom(), config :: any(), - event :: pid() | atom() + sink :: pid() | atom() }). -start_link(Event, Module, Config) -> - gen_server:start_link(?MODULE, [Event, Module, Config], []). +start_link(Sink, Module, Config) -> + gen_server:start_link(?MODULE, [Sink, Module, Config], []). -start(Event, Module, Config) -> - gen_server:start(?MODULE, [Event, Module, Config], []). +start(Sink, Module, Config) -> + gen_server:start(?MODULE, [Sink, Module, Config], []). -init([Event, Module, Config]) -> - install_handler(Event, Module, Config), - {ok, #state{event=Event, module=Module, config=Config}}. +init([Sink, Module, Config]) -> + install_handler(Sink, Module, Config), + {ok, #state{sink=Sink, module=Module, config=Config}}. handle_call(_Call, _From, State) -> {reply, ok, State}. @@ -62,18 +62,18 @@ handle_info({gen_event_EXIT, Module, normal}, #state{module=Module} = State) -> handle_info({gen_event_EXIT, Module, shutdown}, #state{module=Module} = State) -> {stop, normal, State}; handle_info({gen_event_EXIT, Module, Reason}, #state{module=Module, - config=Config, event=Event} = State) -> + config=Config, sink=Sink} = State) -> case lager:log(error, self(), "Lager event handler ~p exited with reason ~s", [Module, error_logger_lager_h:format_reason(Reason)]) of ok -> - install_handler(Event, Module, Config); + install_handler(Sink, Module, Config); {error, _} -> %% lager is not working, so installing a handler won't work ok end, {noreply, State}; -handle_info(reinstall_handler, #state{module=Module, config=Config, event=Event} = State) -> - install_handler(Event, Module, Config), +handle_info(reinstall_handler, #state{module=Module, config=Config, sink=Sink} = State) -> + install_handler(Sink, Module, Config), {noreply, State}; handle_info(stop, State) -> {stop, normal, State}; @@ -88,22 +88,22 @@ code_change(_OldVsn, State, _Extra) -> %% internal -install_handler(Event, Module, Config) -> - case gen_event:add_sup_handler(Event, Module, Config) of +install_handler(Sink, Module, Config) -> + case gen_event:add_sup_handler(Sink, Module, Config) of ok -> - ?INT_LOG(debug, "Lager installed handler ~p into ~p", [Module, Event]), + ?INT_LOG(debug, "Lager installed handler ~p into ~p", [Module, Sink]), lager:update_loglevel_config(), ok; {error, {fatal, Reason}} -> ?INT_LOG(error, "Lager fatally failed to install handler ~p into" - " ~p, NOT retrying: ~p", [Module, Event, Reason]), + " ~p, NOT retrying: ~p", [Module, Sink, Reason]), %% tell ourselves to stop self() ! stop, ok; Error -> %% try to reinstall it later ?INT_LOG(error, "Lager failed to install handler ~p into" - " ~p, retrying later : ~p", [Module, Event, Error]), + " ~p, retrying later : ~p", [Module, Sink, Error]), erlang:send_after(5000, self(), reinstall_handler), ok end. From be758ee3f4c05e63fd39235491b6a351e43a6879 Mon Sep 17 00:00:00 2001 From: Mayorov Andrey Date: Fri, 6 Feb 2015 14:22:48 +0300 Subject: [PATCH 011/102] Provide means to compress printed record output Sometimes there are a LOT of records going through logging backends which contain notable number of empty (i.e. undefined) fields. This humble patch solemnly introduces new function `lager:pr/3` designed to help cope with such kind of issues, providing a one and only option `compress` which, when turned on, effectively eliminates any empty fields in records. --- src/lager.erl | 25 ++++++++++++++++--------- test/compress_pr_record_test.erl | 16 ++++++++++++++++ 2 files changed, 32 insertions(+), 9 deletions(-) create mode 100644 test/compress_pr_record_test.erl diff --git a/src/lager.erl b/src/lager.erl index aa2ac24..ac8035e 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -31,7 +31,7 @@ get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, update_loglevel_config/0, posix_error/1, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/9, - do_log/9, pr/2]). + do_log/9, pr/2, pr/3]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -368,34 +368,41 @@ safe_format_chop(Fmt, Args, Limit) -> safe_format(Fmt, Args, Limit, [{chomp, true}]). %% @doc Print a record lager found during parse transform -pr(Record, Module) when is_tuple(Record), is_atom(element(1, Record)) -> +pr(Record, Module) -> + pr(Record, Module, []). + +%% @doc Print a record lager found during parse transform +pr(Record, Module, Options) when is_tuple(Record), is_atom(element(1, Record)), is_list(Options) -> try case is_record_known(Record, Module) of false -> Record; {RecordName, RecordFields} -> {'$lager_record', RecordName, - zip(RecordFields, tl(tuple_to_list(Record)), Module, [])} + zip(RecordFields, tl(tuple_to_list(Record)), Module, Options, [])} end catch error:undef -> Record end; -pr(Record, _) -> +pr(Record, _, _) -> Record. -zip([FieldName|RecordFields], [FieldValue|Record], Module, ToReturn) -> +zip([FieldName|RecordFields], [FieldValue|Record], Module, Options, ToReturn) -> + Compress = lists:member(compress, Options), case is_tuple(FieldValue) andalso tuple_size(FieldValue) > 0 andalso is_atom(element(1, FieldValue)) andalso is_record_known(FieldValue, Module) of + false when Compress andalso FieldValue =:= undefined -> + zip(RecordFields, Record, Module, Options, ToReturn); false -> - zip(RecordFields, Record, Module, [{FieldName, FieldValue}|ToReturn]); + zip(RecordFields, Record, Module, Options, [{FieldName, FieldValue}|ToReturn]); _Else -> - F = {FieldName, pr(FieldValue, Module)}, - zip(RecordFields, Record, Module, [F|ToReturn]) + F = {FieldName, pr(FieldValue, Module, Options)}, + zip(RecordFields, Record, Module, Options, [F|ToReturn]) end; -zip([], [], _Module, ToReturn) -> +zip([], [], _Module, _Compress, ToReturn) -> lists:reverse(ToReturn). is_record_known(Record, Module) -> diff --git a/test/compress_pr_record_test.erl b/test/compress_pr_record_test.erl new file mode 100644 index 0000000..e3de673 --- /dev/null +++ b/test/compress_pr_record_test.erl @@ -0,0 +1,16 @@ +-module(compress_pr_record_test). + +-compile([{parse_transform, lager_transform}]). + +-record(a, {field1, field2, foo, bar, baz, zyu, zix}). + +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. + +nested_record_test() -> + A = #a{field1 = "Notice me senpai"}, + Pr_A = lager:pr(A, ?MODULE), + Pr_A_Comp = lager:pr(A, ?MODULE, [compress]), + ?assertMatch({'$lager_record', a, [{field1, "Notice me senpai"}, {field2, undefined} | _]}, Pr_A), + ?assertEqual({'$lager_record', a, [{field1, "Notice me senpai"}]}, Pr_A_Comp). From f8cd7ec88834283e5082c1a7ccfae556c802840d Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 17 Mar 2015 13:28:54 -0400 Subject: [PATCH 012/102] More DEFAULT_SINK --- src/lager.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 171c35b..f6dc714 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -314,12 +314,12 @@ status() -> %% @doc Set the loglevel for a particular backend. set_loglevel(Handler, Level) when is_atom(Level) -> - set_loglevel(lager_event, Handler, undefined, Level). + set_loglevel(?DEFAULT_SINK, Handler, undefined, Level). %% @doc Set the loglevel for a particular backend that has multiple identifiers %% (eg. the file backend). set_loglevel(Handler, Ident, Level) when is_atom(Level) -> - set_loglevel(lager_event, Handler, Ident, Level). + set_loglevel(?DEFAULT_SINK, Handler, Ident, Level). %% @doc Set the loglevel for a particular sink's backend that potentially has %% multiple identifiers. (Use `undefined' if it doesn't have any.) From a932df0e7dafe5577659c82024fd537015f69f18 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 17 Mar 2015 14:00:00 -0400 Subject: [PATCH 013/102] To make configuration backwards compatible, I think lager_event stays as a special sink, with other sinks able to be added --- src/lager.app.src | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index e1ed54c..a53e0f6 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -43,8 +43,8 @@ %% Number of rotated crash logs to keep, 0 means keep only the %% current one - default is 0 {crash_log_count, 5}, - %% Whether to redirect error_logger messages into lager - defaults to true - {error_logger_redirect, lager_event}, %% <-- sink name + %% Whether to redirect error_logger messages into the default lager_event sink - defaults to true + {error_logger_redirect, true}, %% How many messages per second to allow from error_logger before we start dropping them {error_logger_hwm, 50}, %% How big the gen_event mailbox can get before it is switched into sync mode @@ -52,8 +52,8 @@ %% Switch back to async mode, when gen_event mailbox size decrease from `async_threshold' %% to async_threshold - async_threshold_window {async_threshold_window, 5}, %% <-- per sink - {sinks, [ - {lager_event, [{async_threshold, 20}, {async_threshold_window, 5}]} + {extra_sinks, [ + {security, []}, %% Security sink has no async behavior ]}, ]} ]}. From c0d859441f8ac11a32078e5d42468ca490c7ce84 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 17 Mar 2015 16:16:59 -0400 Subject: [PATCH 014/102] Rethink configuration, heavily rework lager_app:start for more modularity --- src/lager.app.src | 6 +- src/lager_app.erl | 184 +++++++++++++++++++++++++++------------------- 2 files changed, 114 insertions(+), 76 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index a53e0f6..9f5ad00 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -53,7 +53,11 @@ %% to async_threshold - async_threshold_window {async_threshold_window, 5}, %% <-- per sink {extra_sinks, [ - {security, []}, %% Security sink has no async behavior + {audit, [{lager_file_backend, + [{file, "log/audit.log"}, {level, info}, + {size, 10485760}, {date, "$D0"}, {count, 10}] + } + ]}, %% Security audit sink has no async behavior ]}, ]} ]}. diff --git a/src/lager_app.erl b/src/lager_app.erl index ace1a50..d007ea4 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -29,94 +29,128 @@ start/2, stop/1]). +-define(?THROTTLE, lager_backend_throttle). +-define(?DEFAULT_HANDLER_CONF, + [{lager_console_backend, info}, + {lager_file_backend, + [{file, "log/error.log"}, {level, error}, + {size, 10485760}, {date, "$D0"}, {count, 5}] + }, + {lager_file_backend, + [{file, "log/console.log"}, {level, info}, + {size, 10485760}, {date, "$D0"}, {count, 5}] + } + ]). + start() -> application:start(lager). -start(_StartType, _StartArgs) -> - {ok, Pid} = lager_sup:start_link(), +start_throttle(Sink, Threshold, Window) -> + _ = supervisor:start_child(lager_handler_watcher_sup, + [Sink, ?THROTTLE, [Threshold, Window]]), + ok. +determine_async_behavior(_Sink, {ok, undefined}, _Window) -> + ok; +determine_async_behavior(_Sink, undefined, _Window) -> + ok; +determine_async_behavior(_Sink, {ok, Threshold}, _Window) when not is_integer(Threshold) orelse Threshold < 0 -> + error_logger:error_msg("Invalid value for 'async_threshold': ~p~n", + [Threshold]), + throw({error, bad_config}); +determine_async_behavior(Sink, {ok, Threshold}, undefined) + start_throttle(Sink, Threshold, erlang:trunc(Threshold * 0.2)); +determine_async_behavior(_Sink, {ok, Threshold}, {ok, Window}) when not is_integer(Window) orelse Window > Threshold orelse Window < 0 -> + error_logger:error_msg( + "Invalid value for 'async_threshold_window': ~p~n", [Window]), + throw({error, bad_config}); +determine_async_behavior(Sink, {ok, Threshold}, {ok, Window}) -> + start_throttle(Sink, Threshold, Window). - case application:get_env(lager, async_threshold) of - undefined -> - ok; - {ok, undefined} -> - undefined; - {ok, Threshold} when is_integer(Threshold), Threshold >= 0 -> - DefWindow = erlang:trunc(Threshold * 0.2), % maybe 0? - ThresholdWindow = - case application:get_env(lager, async_threshold_window) of - undefined -> - DefWindow; - {ok, Window} when is_integer(Window), Window < Threshold, Window >= 0 -> - Window; - {ok, BadWindow} -> - error_logger:error_msg( - "Invalid value for 'async_threshold_window': ~p~n", [BadWindow]), - throw({error, bad_config}) - end, - _ = supervisor:start_child(lager_handler_watcher_sup, - [lager_event, lager_backend_throttle, [Threshold, ThresholdWindow]]), - ok; - {ok, BadThreshold} -> - error_logger:error_msg("Invalid value for 'async_threshold': ~p~n", [BadThreshold]), - throw({error, bad_config}) - end, +start_handlers(_Sink, undefined) -> + ok; +start_handlers(_Sink, {ok, Handlers}) when not is_list(Handlers) -> + error_logger:error_msg( + "Invalid value for 'handlers' (must be list): ~p~n", [Handlers]), + throw({error, bad_config}); +start_handlers(Sink, {ok, Handlers}) -> + %% handlers failing to start are handled in the handler_watcher + _ = [supervisor:start_child(lager_handler_watcher_sup, + [Sink, Module, Config]) || + {Module, Config} <- expand_handlers(Handlers)], + ok. - %% TODO: - %% Read config for other event sinks here and start them appropriately +interpret_hwm(undefined) -> + undefined; +interpret_hwm({ok, undefined}) -> + undefined; +interpret_hwm({ok, HWM}) when not is_integer(HWM) orelse HWM < 0 -> + _ = lager:log(warning, self(), "Invalid error_logger high water mark: ~p, disabling", [HWM]), + undefined; +interpret_hwm({ok, HWM}) -> + HWM. - Handlers = case application:get_env(lager, handlers) of - undefined -> - [{lager_console_backend, info}, - {lager_file_backend, [{file, "log/error.log"}, {level, error}, {size, 10485760}, {date, "$D0"}, {count, 5}]}, - {lager_file_backend, [{file, "log/console.log"}, {level, info}, {size, 10485760}, {date, "$D0"}, {count, 5}]}]; - {ok, Val} -> - Val - end, +start_error_logger_handler({ok, false}, _HWM, _Whitelist) -> + []; +start_error_logger_handler(_, HWM, undefined) -> + start_error_logger_handler(ignore_me, HWM, {ok, []}); +start_error_logger_handler(_, HWM, {ok, WhiteList}) -> + case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HWM]]) of + {ok, _} -> + [begin error_logger:delete_report_handler(X), X end || + X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h | WhiteList]]; + {error, _} -> + [] + end. - %% handlers failing to start are handled in the handler_watcher - _ = [supervisor:start_child(lager_handler_watcher_sup, [lager_event, Module, Config]) || - {Module, Config} <- expand_handlers(Handlers)], +wrap_proplist_value(undefined) -> + undefined; +wrap_proplist_value(Value) -> + {ok, Value}. + +configure_sink(Sink, SinkDef) -> + determine_async_behavior(Sink, + wrap_proplist_value( + proplists:get_value(async_threshold, SinkDef)), + wrap_proplist_value( + proplists:get_value(async_threshold_window, SinkDef)) + ), + start_handlers(Sink, + wrap_proplist_value( + proplists:get_value(handlers, SinkDef, [])) + ), + + lager:update_loglevel_config(Sink). + + +configure_extra_sinks(Sinks) -> + lists:foreach(fun({Sink, Proplist}) -> configure_sink(Sink, Proplist) end, + Sinks). + +start(_StartType, _StartArgs) -> + {ok, Pid} = lager_sup:start_link(), + + %% Handle the default sink. + determine_async_behavior(?DEFAULT_SINK, + application:get_env(lager, async_threshold), + application:get_env(lager, async_threshold_window)), + start_handlers(?DEFAULT_SINK, + application:get_env(lager, handlers, ?DEFAULT_HANDLER_CONF)), ok = add_configured_traces(), - %% mask the messages we have no use for - lager:update_loglevel_config(), - - HighWaterMark = case application:get_env(lager, error_logger_hwm) of - {ok, undefined} -> - undefined; - {ok, HwmVal} when is_integer(HwmVal), HwmVal > 0 -> - HwmVal; - {ok, BadVal} -> - _ = lager:log(warning, self(), "Invalid error_logger high water mark: ~p, disabling", [BadVal]), - undefined; - undefined -> - undefined - end, + lager:update_loglevel_config(?DEFAULT_SINK), - SavedHandlers = - case application:get_env(lager, error_logger_redirect) of - {ok, false} -> - []; - _ -> - WhiteList = case application:get_env(lager, error_logger_whitelist) of - undefined -> - []; - {ok, WhiteList0} -> - WhiteList0 - end, - - case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HighWaterMark]]) of - {ok, _} -> - [begin error_logger:delete_report_handler(X), X end || - X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h | WhiteList]]; - {error, _} -> - [] - end - end, + SavedHandlers = start_error_logger_handler( + application:get_env(lager, error_logger_redirect), + interpret_hwm(application:get_env(lager, error_logger_hwm)), + application:get_env(lager, error_logger_whitelist) + ), + + _ = lager_util:trace_filter(none), - _ = lager_util:trace_filter(none), + %% Now handle extra sinks + configure_extra_sinks(application:get_env(lager, extra_sinks, [])), {ok, Pid, SavedHandlers}. From 6f6b0110f2600fe096600240fbbd64e15c6977a5 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Thu, 19 Mar 2015 17:40:38 -0400 Subject: [PATCH 015/102] Starting down the path of making backends handle multiple sinks (primary use case is tracing) --- src/lager.erl | 37 ++++++++++++++++++++++------------- src/lager_app.erl | 15 +++++++++++--- src/lager_config.erl | 19 +++++++++++++++--- src/lager_file_backend.erl | 2 +- src/lager_handler_watcher.erl | 15 ++++++++++++-- 5 files changed, 65 insertions(+), 23 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index f6dc714..6125415 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -21,6 +21,7 @@ -include("lager.hrl"). -define(LAGER_MD_KEY, '__lager_metadata'). +-define(TRACE_SINK, '__trace_sink'). %% API -export([start/0, @@ -173,16 +174,24 @@ trace_file(File, Filter, Level, Options) -> Trace0 = {Filter, Level, {lager_file_backend, File}}, case lager_util:validate_trace(Trace0) of {ok, Trace} -> - Handlers = gen_event:which_handlers(lager_event), + Handlers = lager_config:global_get(handlers, []), %% check if this file backend is already installed - Res = case lists:member({lager_file_backend, File}, Handlers) of - false -> - %% install the handler - LogFileConfig = lists:keystore(level, 1, lists:keystore(file, 1, Options, {file, File}), {level, none}), - supervisor:start_child(lager_handler_watcher_sup, - [lager_event, {lager_file_backend, File}, LogFileConfig]); - _ -> - {ok, exists} + Res = case lists:keyfind({lager_file_backend, File}, 2, Handlers) of + false -> + %% install the handler + LogFileConfig = + lists:keystore(level, 1, + lists:keystore(file, 1, + Options, + {file, File}), + {level, none}), + HandlerInfo = + lager_app:start_handler(?TRACE_SINK, lager_file_backend, + LogFileConfig), + lager_config:global_set(handlers, [HandlerInfo|Handlers]); + {Watcher, _Handler} -> + lager_handler_watcher:add_sink(Watcher, ?TRACE_SINK), + {ok, exists} end, case Res of {ok, _} -> @@ -250,17 +259,17 @@ stop_trace_int({Backend, _Filter, _Level} = Trace) -> ok. clear_all_traces() -> - {Level, _Traces} = lager_config:get(loglevel), + Handlers = lager_config:global_get(handlers, []), _ = lager_util:trace_filter(none), - lager_config:set(loglevel, {Level, []}), - lists:foreach(fun(Handler) -> + lists:foreach(fun({Watcher, Handler}) -> case get_loglevel(Handler) of none -> - gen_event:delete_handler(lager_event, Handler, []); + gen_event:delete_handler(?TRACE_SINK, Handler, []), + langer_handler_watcher:remove_sink(Watcher, ?TRACE_SINK) _ -> ok end - end, gen_event:which_handlers(lager_event)). + end, Handlers). status() -> Handlers = gen_event:which_handlers(lager_event), diff --git a/src/lager_app.erl b/src/lager_app.erl index d007ea4..c7c9208 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -27,6 +27,7 @@ -endif. -export([start/0, start/2, + start_handler/3, stop/1]). -define(?THROTTLE, lager_backend_throttle). @@ -75,11 +76,19 @@ start_handlers(_Sink, {ok, Handlers}) when not is_list(Handlers) -> throw({error, bad_config}); start_handlers(Sink, {ok, Handlers}) -> %% handlers failing to start are handled in the handler_watcher - _ = [supervisor:start_child(lager_handler_watcher_sup, - [Sink, Module, Config]) || - {Module, Config} <- expand_handlers(Handlers)], + lager_config:global_set(handlers, + lists:map(fun({Module, Config}) -> + start_handler(Sink, Module, Config) + end, + expand_handlers(Handlers))), ok. +start_handler(Sink, Module, Config) -> + {ok, Watcher} = supervisor:start_child(lager_handler_watcher_sup, + [Sink, Module, Config]), + BackendId = Module:config_to_id(Config), + {BackendId, Watcher}. + interpret_hwm(undefined) -> undefined; interpret_hwm({ok, undefined}) -> diff --git a/src/lager_config.erl b/src/lager_config.erl index 263604c..cf2c793 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -20,12 +20,14 @@ -include("lager.hrl"). --export([new/0, get/1, get/2, get/3, set/2, set/3]). +-export([new/0, get/1, get/2, get/3, set/2, set/3, + global_get/1, global_get/2, global_set/2]). -define(TBL, lager_config). +-define(GLOBAL, '_global'). %% For multiple sinks, the key is now the registered event name and the old key -%% as a tuple. +%% as a tuple. %% %% {{lager_event, loglevel}, Value} instead of {loglevel, Value} @@ -41,9 +43,20 @@ new() -> %% use insert_new here so that if we're in an appup we don't mess anything up %% %% until lager is completely started, allow all messages to go through - ets:insert_new(?TBL, {{lager_event, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}}), + ets:insert_new(?TBL, {{lager_event, loglevel}, {element(2, lager_util:config_to_mask(debug))}}), + %% Need to be able to find the `lager_handler_watcher' for all handlers + ets:insert_new(?TBL, {{?GLOBAL, handlers}, []}), ok. +global_get(Key) -> + global_get(Key, undefined). + +global_get(Key, Default) -> + get(?GLOBAL, Key, Default). + +global_set(Key, Value) -> + set(?GLOBAL, Key, Value). + get(Key) -> get(?DEFAULT_SINK, Key, undefined). diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index f5ab2c9..30439fe 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -164,7 +164,7 @@ terminate(_Reason, #state{fd=FD}) -> code_change(_OldVsn, State, _Extra) -> {ok, State}. -%% @private convert the config into a gen_event handler ID +%% Convert the config into a gen_event handler ID config_to_id({Name,_Severity}) when is_list(Name) -> {?MODULE, Name}; config_to_id({Name,_Severity,_Size,_Rotation,_Count}) -> diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index af0844d..0dc3a98 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -33,12 +33,12 @@ -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). --export([start_link/3, start/3]). +-export([start_link/3, start/3, add_sink/2, remove_sink/2]). -record(state, { module :: atom(), config :: any(), - sink :: pid() | atom() + sinks :: list(pid() | atom()) }). start_link(Sink, Module, Config) -> @@ -47,13 +47,24 @@ start_link(Sink, Module, Config) -> start(Sink, Module, Config) -> gen_server:start(?MODULE, [Sink, Module, Config], []). +remove_sink(Pid, Sink) -> + gen_server:call(Pid, {remove_sink, Sink}). + +add_sink(Pid, Sink) -> + gen_server:call(Pid, {add_sink, Sink}). + init([Sink, Module, Config]) -> install_handler(Sink, Module, Config), {ok, #state{sink=Sink, module=Module, config=Config}}. +handle_call({remove_sink, Sink}, _From, #state{sinks=Sinks}=State) -> + {reply, ok, State#{sinks=lists:delete(Sink, Sinks)}}; +handle_call({add_sink, Sink}, _From, #state{sinks=Sinks}=State) -> + {reply, ok, State#{sinks=[Sink|Sinks]}}; handle_call(_Call, _From, State) -> {reply, ok, State}. + handle_cast(_Request, State) -> {noreply, State}. From db697bc7206f76564ff84f4d418e338a41810514 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 09:21:46 -0400 Subject: [PATCH 016/102] Revert last change: we are not (yet) allowing backends to watch multiple sinks --- src/lager_handler_watcher.erl | 15 ++------------- 1 file changed, 2 insertions(+), 13 deletions(-) diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index 0dc3a98..af0844d 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -33,12 +33,12 @@ -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). --export([start_link/3, start/3, add_sink/2, remove_sink/2]). +-export([start_link/3, start/3]). -record(state, { module :: atom(), config :: any(), - sinks :: list(pid() | atom()) + sink :: pid() | atom() }). start_link(Sink, Module, Config) -> @@ -47,24 +47,13 @@ start_link(Sink, Module, Config) -> start(Sink, Module, Config) -> gen_server:start(?MODULE, [Sink, Module, Config], []). -remove_sink(Pid, Sink) -> - gen_server:call(Pid, {remove_sink, Sink}). - -add_sink(Pid, Sink) -> - gen_server:call(Pid, {add_sink, Sink}). - init([Sink, Module, Config]) -> install_handler(Sink, Module, Config), {ok, #state{sink=Sink, module=Module, config=Config}}. -handle_call({remove_sink, Sink}, _From, #state{sinks=Sinks}=State) -> - {reply, ok, State#{sinks=lists:delete(Sink, Sinks)}}; -handle_call({add_sink, Sink}, _From, #state{sinks=Sinks}=State) -> - {reply, ok, State#{sinks=[Sink|Sinks]}}; handle_call(_Call, _From, State) -> {reply, ok, State}. - handle_cast(_Request, State) -> {noreply, State}. From cc7e4d26d410c6dedf1946b5d8df898f0a9cadc3 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 09:37:10 -0400 Subject: [PATCH 017/102] Start incorporating support for dedicated tracing sink --- src/lager.erl | 42 ++++++++++++++++++++++++------------------ 1 file changed, 24 insertions(+), 18 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 6125415..4c68cf2 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -31,8 +31,8 @@ clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/1, update_loglevel_config/1, posix_error/1, - safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, - do_log/9, pr/2]). + safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, + do_log/10, pr/2]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -93,19 +93,19 @@ dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity case {whereis(Sink), lager_config:get(Sink, loglevel, {?LOG_NONE, []})} of {undefined, _} -> {error, lager_not_running}; - {Pid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> - do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Pid); + {SinkPid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> + do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); _ -> ok end. %% @private Should only be called externally from code generated from the parse transform -do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Pid) when is_atom(Severity) -> - Destinations = case TraceFilters of +do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> + {Destinations, TraceSinkPid} = case TraceFilters of [] -> - []; + {[], undefined}; _ -> - lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[]) + {lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[]), whereis(?TRACE_SINK)} end, case (LevelThreshold band SeverityAsInt) /= 0 orelse Destinations /= [] of true -> @@ -119,9 +119,15 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr Severity, Metadata, Destinations), case lager_config:get(Sink, async, false) of %% this needs to be able to get value from a non-default sink true -> - gen_event:notify(Pid, {log, LagerMsg}); + gen_event:notify(SinkPid, {log, LagerMsg}); false -> - gen_event:sync_notify(Pid, {log, LagerMsg}) + gen_event:sync_notify(SinkPid, {log, LagerMsg}) + end, + case TraceSinkPid =/ undefined of + true -> + gen_event:notify(TraceSinkPid, {log, LagerMsg}); + false -> + ok end; false -> ok @@ -312,7 +318,7 @@ status() -> ], [ "Tracing Statistics:\n ", - [ begin + [ begin [" ", atom_to_list(Table), ": ", integer_to_list(?DEFAULT_TRACER:info(Table) div TraceCount), "\n"] @@ -334,8 +340,8 @@ set_loglevel(Handler, Ident, Level) when is_atom(Level) -> %% multiple identifiers. (Use `undefined' if it doesn't have any.) set_loglevel(Sink, Handler, Ident, Level) when is_atom(Level) -> HandlerArg = case Ident of - undefined -> Handler; - _ -> {Handler, Ident} + undefined -> Handler; + _ -> {Handler, Ident} end, Reply = gen_event:call(Sink, HandlerArg, {set_loglevel, Level}, infinity), update_loglevel_config(Sink), @@ -425,12 +431,12 @@ safe_format_chop(Fmt, Args, Limit) -> %% @doc Print a record lager found during parse transform pr(Record, Module) when is_tuple(Record), is_atom(element(1, Record)) -> - try + try case is_record_known(Record, Module) of false -> Record; {RecordName, RecordFields} -> - {'$lager_record', RecordName, + {'$lager_record', RecordName, zip(RecordFields, tl(tuple_to_list(Record)), Module, [])} end catch @@ -454,15 +460,15 @@ zip([FieldName|RecordFields], [FieldValue|Record], Module, ToReturn) -> zip([], [], _Module, ToReturn) -> lists:reverse(ToReturn). -is_record_known(Record, Module) -> +is_record_known(Record, Module) -> Name = element(1, Record), Attrs = Module:module_info(attributes), case lists:keyfind(lager_records, 1, Attrs) of false -> false; - {lager_records, Records} -> + {lager_records, Records} -> case lists:keyfind(Name, 1, Records) of false -> false; - {Name, RecordFields} -> + {Name, RecordFields} -> case (tuple_size(Record) - 1) =:= length(RecordFields) of false -> false; true -> {Name, RecordFields} From 0ec113132bd06b80bc9fac91ac95ac442a30a7f3 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 11:23:58 -0400 Subject: [PATCH 018/102] Traces now are assigned to a single sink as requested (or lager_event by default) --- src/lager.erl | 75 +++++++++++++++++++++++++---------------------- src/lager_app.erl | 4 +-- 2 files changed, 42 insertions(+), 37 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 4c68cf2..80f6b45 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -163,6 +163,16 @@ log(Sink, Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> log(Sink, Level, Metadata, Format, Args) when is_list(Metadata) -> dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION). +validate_trace_filters(Filters, Level, Backend) -> + Sink = proplists:get_value(sink, Filters, ?DEFAULT_SINK), + {Sink, + lager_util:validate_trace({ + proplists:delete(sink, Filters), + Level, + Backend + }) + }. + trace_file(File, Filter) -> trace_file(File, Filter, debug, []). @@ -172,14 +182,9 @@ trace_file(File, Filter, Level) when is_atom(Level) -> trace_file(File, Filter, Options) when is_list(Options) -> trace_file(File, Filter, debug, Options). -%% FIXME: All of this code assumes a single event handler -%% In fact anywhere there's `lager_event' assume that the code -%% should be generalized to support multiple sinks. - trace_file(File, Filter, Level, Options) -> - Trace0 = {Filter, Level, {lager_file_backend, File}}, - case lager_util:validate_trace(Trace0) of - {ok, Trace} -> + case validate_trace_filters(Filter, Level, {lager_file_backend, File}) of + {Sink, {ok, Trace}} -> Handlers = lager_config:global_get(handlers, []), %% check if this file backend is already installed Res = case lists:keyfind({lager_file_backend, File}, 2, Handlers) of @@ -192,21 +197,23 @@ trace_file(File, Filter, Level, Options) -> {file, File}), {level, none}), HandlerInfo = - lager_app:start_handler(?TRACE_SINK, lager_file_backend, + lager_app:start_handler(Sink, lager_file_backend, LogFileConfig), lager_config:global_set(handlers, [HandlerInfo|Handlers]); - {Watcher, _Handler} -> - lager_handler_watcher:add_sink(Watcher, ?TRACE_SINK), - {ok, exists} + {Watcher, _Handler, Sink} -> + {ok, exists}; + {Watcher, _Handler, OtherSink} -> + {error, file_in_use} end, case Res of {ok, _} -> - add_trace_to_loglevel_config(Trace), + %% XXX Double-check this logic for {ok, exists} + add_trace_to_loglevel_config(Trace, Sink), {ok, {{lager_file_backend, File}, Filter, Level}}; {error, _} = E -> E end; - Error -> + {_Sink, Error} -> Error end. @@ -223,39 +230,37 @@ trace({lager_file_backend, File}, Filter, Level) -> trace_file(File, Filter, Level); trace(Backend, Filter, Level) -> - Trace0 = {Filter, Level, Backend}, - case lager_util:validate_trace(Trace0) of - {ok, Trace} -> - add_trace_to_loglevel_config(Trace), + case validate_trace_filters(Filter, Level, Backend) of + {Sink, {ok, Trace}} -> + add_trace_to_loglevel_config(Trace, Sink), {ok, {Backend, Filter, Level}}; - Error -> + {_Sink, Error} -> Error end. stop_trace(Backend, Filter, Level) -> - Trace0 = {Filter, Level, Backend}, - case lager_util:validate_trace(Trace0) of - {ok, Trace} -> - stop_trace_int(Trace); - Error -> + case validate_trace_filters(Filter, Level, Backend) of + {Sink, {ok, Trace}} -> + stop_trace_int(Trace, Sink); + {_Sink, Error} -> Error end. stop_trace({Backend, Filter, Level}) -> stop_trace(Backend, Filter, Level). -stop_trace_int({Backend, _Filter, _Level} = Trace) -> - {Level, Traces} = lager_config:get(loglevel), +stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> + {Level, Traces} = lager_config:get(Sink, loglevel), NewTraces = lists:delete(Trace, Traces), _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces ]), %MinLevel = minimum_loglevel(get_loglevels() ++ get_trace_levels(NewTraces)), - lager_config:set(loglevel, {Level, NewTraces}), - case get_loglevel(Backend) of + lager_config:set(Sink, loglevel, {Level, NewTraces}), + case get_loglevel(Sink, Backend) of none -> %% check no other traces point here case lists:keyfind(Backend, 3, NewTraces) of false -> - gen_event:delete_handler(lager_event, Backend, []); + gen_event:delete_handler(Sink, Backend, []); _ -> ok end; @@ -267,18 +272,18 @@ stop_trace_int({Backend, _Filter, _Level} = Trace) -> clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), _ = lager_util:trace_filter(none), - lists:foreach(fun({Watcher, Handler}) -> + lists:foreach(fun({Watcher, Handler, Sink}) -> case get_loglevel(Handler) of none -> - gen_event:delete_handler(?TRACE_SINK, Handler, []), - langer_handler_watcher:remove_sink(Watcher, ?TRACE_SINK) + gen_event:delete_handler(Sink, Handler, []), _ -> ok end end, Handlers). +%% XXX Needs heavy revision status() -> - Handlers = gen_event:which_handlers(lager_event), + Handlers = lager_config:global_get(handlers, []), TraceCount = case length(element(2, lager_config:get(loglevel))) of 0 -> 1; N -> N @@ -383,13 +388,13 @@ get_loglevels(Sink) -> Handler <- gen_event:which_handlers(Sink)]. %% @private -add_trace_to_loglevel_config(Trace) -> - {MinLevel, Traces} = lager_config:get(loglevel), +add_trace_to_loglevel_config(Trace, Sink) -> + {MinLevel, Traces} = lager_config:get(Sink, loglevel), case lists:member(Trace, Traces) of false -> NewTraces = [Trace|Traces], _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces]), - lager_config:set(lager_event, loglevel, {MinLevel, [Trace|Traces]}); + lager_config:set(Sink, loglevel, {MinLevel, [Trace|Traces]}); _ -> ok end. diff --git a/src/lager_app.erl b/src/lager_app.erl index c7c9208..327753b 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -87,7 +87,7 @@ start_handler(Sink, Module, Config) -> {ok, Watcher} = supervisor:start_child(lager_handler_watcher_sup, [Sink, Module, Config]), BackendId = Module:config_to_id(Config), - {BackendId, Watcher}. + {BackendId, Watcher, Sink}. interpret_hwm(undefined) -> undefined; @@ -199,7 +199,7 @@ add_configured_traces() -> maybe_make_handler_id(Mod, Config) -> %% Allow the backend to generate a gen_event handler id, if it wants to. - %% We don't use erlang:function_exported here because that requires the module + %% We don't use erlang:function_exported here because that requires the module %% already be loaded, which is unlikely at this phase of startup. Using code:load %% caused undesireable side-effects with generating code-coverage reports. try Mod:config_to_id(Config) of From 53488fcb1a92742276887ed5340a5a4a19dccf39 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 13:36:50 -0400 Subject: [PATCH 019/102] Trailing commas, my old enemy --- src/lager.app.src | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index 9f5ad00..c191b94 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -13,9 +13,9 @@ {registered, [lager_sup, lager_event, lager_crash_log, lager_handler_watcher_sup]}, {mod, {lager_app, []}}, {env, [ - %% Note: application:start(lager) overwrites previously defined environment variables + %% Note: application:start(lager) overwrites previously defined environment variables %% thus declaration of default handlers is done at lager_app.erl - + %% What colors to use with what log levels {colored, false}, {colors, [ @@ -57,7 +57,7 @@ [{file, "log/audit.log"}, {level, info}, {size, 10485760}, {date, "$D0"}, {count, 10}] } - ]}, %% Security audit sink has no async behavior - ]}, + ]} %% Security audit sink has no async behavior + ]} ]} ]}. From 21fd439a6f74cbfae8c5916909f1e72379e74a77 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 13:38:06 -0400 Subject: [PATCH 020/102] Stupid compiler errors --- src/lager_app.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 327753b..db670d6 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -30,8 +30,8 @@ start_handler/3, stop/1]). --define(?THROTTLE, lager_backend_throttle). --define(?DEFAULT_HANDLER_CONF, +-define(THROTTLE, lager_backend_throttle). +-define(DEFAULT_HANDLER_CONF, [{lager_console_backend, info}, {lager_file_backend, [{file, "log/error.log"}, {level, error}, @@ -59,7 +59,7 @@ determine_async_behavior(_Sink, {ok, Threshold}, _Window) when not is_integer(Th error_logger:error_msg("Invalid value for 'async_threshold': ~p~n", [Threshold]), throw({error, bad_config}); -determine_async_behavior(Sink, {ok, Threshold}, undefined) +determine_async_behavior(Sink, {ok, Threshold}, undefined) -> start_throttle(Sink, Threshold, erlang:trunc(Threshold * 0.2)); determine_async_behavior(_Sink, {ok, Threshold}, {ok, Window}) when not is_integer(Window) orelse Window > Threshold orelse Window < 0 -> error_logger:error_msg( From efd3164248e60bdfc4b8c0283262da4888195854 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 13:39:34 -0400 Subject: [PATCH 021/102] Stupid compiler errors --- src/lager.erl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 80f6b45..c01693e 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -123,7 +123,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr false -> gen_event:sync_notify(SinkPid, {log, LagerMsg}) end, - case TraceSinkPid =/ undefined of + case TraceSinkPid /= undefined of true -> gen_event:notify(TraceSinkPid, {log, LagerMsg}); false -> @@ -200,9 +200,9 @@ trace_file(File, Filter, Level, Options) -> lager_app:start_handler(Sink, lager_file_backend, LogFileConfig), lager_config:global_set(handlers, [HandlerInfo|Handlers]); - {Watcher, _Handler, Sink} -> + {_Watcher, _Handler, Sink} -> {ok, exists}; - {Watcher, _Handler, OtherSink} -> + {_Watcher, _Handler, _OtherSink} -> {error, file_in_use} end, case Res of @@ -272,10 +272,10 @@ stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), _ = lager_util:trace_filter(none), - lists:foreach(fun({Watcher, Handler, Sink}) -> + lists:foreach(fun({_Watcher, Handler, Sink}) -> case get_loglevel(Handler) of none -> - gen_event:delete_handler(Sink, Handler, []), + gen_event:delete_handler(Sink, Handler, []); _ -> ok end From b88e95ea42bb4526dc074a31698ed4bc72bdaa67 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 13:44:57 -0400 Subject: [PATCH 022/102] macro ftw --- src/lager_config.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_config.erl b/src/lager_config.erl index cf2c793..e2a7a80 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -43,7 +43,7 @@ new() -> %% use insert_new here so that if we're in an appup we don't mess anything up %% %% until lager is completely started, allow all messages to go through - ets:insert_new(?TBL, {{lager_event, loglevel}, {element(2, lager_util:config_to_mask(debug))}}), + ets:insert_new(?TBL, {{?DEFAULT_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug))}}), %% Need to be able to find the `lager_handler_watcher' for all handlers ets:insert_new(?TBL, {{?GLOBAL, handlers}, []}), ok. From b724b6bd42f97174f032f4df897cb699c63c2f88 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 13:57:40 -0400 Subject: [PATCH 023/102] Monads...still do not know what they are but I know I need em --- src/lager_app.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index db670d6..ef3549d 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -144,7 +144,7 @@ start(_StartType, _StartArgs) -> application:get_env(lager, async_threshold), application:get_env(lager, async_threshold_window)), start_handlers(?DEFAULT_SINK, - application:get_env(lager, handlers, ?DEFAULT_HANDLER_CONF)), + application:get_env(lager, handlers, {ok, ?DEFAULT_HANDLER_CONF})), ok = add_configured_traces(), From ba5548e057ad93ca96033fc698cf95d9d6eab69a Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 14:01:08 -0400 Subject: [PATCH 024/102] update_loglevel_config now takes a sink argument --- src/lager_handler_watcher.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index af0844d..73722ac 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -92,7 +92,7 @@ install_handler(Sink, Module, Config) -> case gen_event:add_sup_handler(Sink, Module, Config) of ok -> ?INT_LOG(debug, "Lager installed handler ~p into ~p", [Module, Sink]), - lager:update_loglevel_config(), + lager:update_loglevel_config(Sink), ok; {error, {fatal, Reason}} -> ?INT_LOG(error, "Lager fatally failed to install handler ~p into" From 2926dd51a1e0955a19192c17558e5e768b137181 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 14:10:18 -0400 Subject: [PATCH 025/102] get/2 was confusing: Sink, Key or Key, Default. Clean up by forcing into {Sink, Key} tuple --- src/lager.erl | 16 ++++++++-------- src/lager_config.erl | 18 +++++++++--------- 2 files changed, 17 insertions(+), 17 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index c01693e..c1e094d 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -90,7 +90,7 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> %% this is the same check that the parse transform bakes into the module at compile time dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> SeverityAsInt=lager_util:level_to_num(Severity), - case {whereis(Sink), lager_config:get(Sink, loglevel, {?LOG_NONE, []})} of + case {whereis(Sink), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of {undefined, _} -> {error, lager_not_running}; {SinkPid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> @@ -117,7 +117,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr end, LagerMsg = lager_msg:new(Msg, Severity, Metadata, Destinations), - case lager_config:get(Sink, async, false) of %% this needs to be able to get value from a non-default sink + case lager_config:get({Sink, async}, false) of %% this needs to be able to get value from a non-default sink true -> gen_event:notify(SinkPid, {log, LagerMsg}); false -> @@ -250,11 +250,11 @@ stop_trace({Backend, Filter, Level}) -> stop_trace(Backend, Filter, Level). stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> - {Level, Traces} = lager_config:get(Sink, loglevel), + {Level, Traces} = lager_config:get({Sink, loglevel}), NewTraces = lists:delete(Trace, Traces), _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces ]), %MinLevel = minimum_loglevel(get_loglevels() ++ get_trace_levels(NewTraces)), - lager_config:set(Sink, loglevel, {Level, NewTraces}), + lager_config:set({Sink, loglevel}, {Level, NewTraces}), case get_loglevel(Sink, Backend) of none -> %% check no other traces point here @@ -389,21 +389,21 @@ get_loglevels(Sink) -> %% @private add_trace_to_loglevel_config(Trace, Sink) -> - {MinLevel, Traces} = lager_config:get(Sink, loglevel), + {MinLevel, Traces} = lager_config:get({Sink, loglevel}), case lists:member(Trace, Traces) of false -> NewTraces = [Trace|Traces], _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces]), - lager_config:set(Sink, loglevel, {MinLevel, [Trace|Traces]}); + lager_config:set({Sink, loglevel}, {MinLevel, [Trace|Traces]}); _ -> ok end. %% @doc recalculate min log level update_loglevel_config(Sink) -> - {_, Traces} = lager_config:get(Sink, loglevel), + {_, Traces} = lager_config:get({Sink, loglevel}), MinLog = minimum_loglevel(get_loglevels(Sink)), - lager_config:set(Sink, loglevel, {MinLog, Traces}). + lager_config:set({Sink, loglevel}, {MinLog, Traces}). %% @private minimum_loglevel(Levels) -> diff --git a/src/lager_config.erl b/src/lager_config.erl index e2a7a80..324dfc9 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -20,7 +20,7 @@ -include("lager.hrl"). --export([new/0, get/1, get/2, get/3, set/2, set/3, +-export([new/0, get/1, get/2, set/2, global_get/1, global_get/2, global_set/2]). -define(TBL, lager_config). @@ -57,13 +57,11 @@ global_get(Key, Default) -> global_set(Key, Value) -> set(?GLOBAL, Key, Value). -get(Key) -> - get(?DEFAULT_SINK, Key, undefined). -get(Key, Default) -> - get(?DEFAULT_SINK, Key, Default). +get(Key) -> + get({?DEFAULT_SINK, Key}, undefined). -get(Sink, Key, Default) -> +get({Sink, Key}, Default) -> try case ets:lookup(?TBL, {Sink, Key}) of [] -> @@ -74,10 +72,12 @@ get(Sink, Key, Default) -> catch _:_ -> Default - end. + end; +get(Key, Default) -> + get({?DEFAULT_SINK, Key}, Default). set(Key, Value) -> - set(?DEFAULT_SINK, Key, Value). + set({?DEFAULT_SINK, Key}, Value). -set(Sink, Key, Value) -> +set({Sink, Key}, Value) -> ets:insert(?TBL, {{Sink, Key}, Value}). From 612dd4e65a87169bc446fc1aa61f279955e21bbe Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 14:11:25 -0400 Subject: [PATCH 026/102] Finish fixing get/set. Got out of the habit of compiling before committing, oops --- src/lager_config.erl | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/src/lager_config.erl b/src/lager_config.erl index 324dfc9..c09333a 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -52,10 +52,10 @@ global_get(Key) -> global_get(Key, undefined). global_get(Key, Default) -> - get(?GLOBAL, Key, Default). + get({?GLOBAL, Key}, Default). global_set(Key, Value) -> - set(?GLOBAL, Key, Value). + set({?GLOBAL, Key}, Value). get(Key) -> @@ -76,8 +76,7 @@ get({Sink, Key}, Default) -> get(Key, Default) -> get({?DEFAULT_SINK, Key}, Default). +set({Sink, Key}, Value) -> + ets:insert(?TBL, {{Sink, Key}, Value}); set(Key, Value) -> set({?DEFAULT_SINK, Key}, Value). - -set({Sink, Key}, Value) -> - ets:insert(?TBL, {{Sink, Key}, Value}). From 8fae61af12e5e4e04993ff3951684acd4274a9a1 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 14:31:32 -0400 Subject: [PATCH 027/102] More config tweaks --- src/lager_config.erl | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/lager_config.erl b/src/lager_config.erl index c09333a..962c387 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -43,7 +43,7 @@ new() -> %% use insert_new here so that if we're in an appup we don't mess anything up %% %% until lager is completely started, allow all messages to go through - ets:insert_new(?TBL, {{?DEFAULT_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug))}}), + ets:insert_new(?TBL, {{?DEFAULT_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}}), %% Need to be able to find the `lager_handler_watcher' for all handlers ets:insert_new(?TBL, {{?GLOBAL, handlers}, []}), ok. @@ -58,6 +58,8 @@ global_set(Key, Value) -> set({?GLOBAL, Key}, Value). +get({_Sink, _Key}=FullKey) -> + get(FullKey, undefined); get(Key) -> get({?DEFAULT_SINK, Key}, undefined). From a462c046fe1b2f1f1c19cf53f6270e15c316cdb0 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 23:15:36 -0400 Subject: [PATCH 028/102] Various bugfixes of various levels of desperation --- src/error_logger_lager_h.erl | 4 ++-- src/lager.app.src | 6 ++++-- src/lager.erl | 4 ++-- src/lager_app.erl | 4 ++-- src/lager_backend_throttle.erl | 12 ++++++------ src/lager_console_backend.erl | 3 +-- src/lager_file_backend.erl | 7 ++++--- src/lager_handler_watcher.erl | 5 ++++- 8 files changed, 25 insertions(+), 20 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index ec0bfb2..6b55b79 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -74,7 +74,7 @@ set_high_water(N) -> gen_event:call(error_logger, ?MODULE, {set_high_water, N}, infinity). -spec init(any()) -> {ok, #state{}}. -init([HighWaterMark]) -> +init([{sink, Sink}, HighWaterMark]) -> {ok, #state{hwm=HighWaterMark}}. handle_call({set_high_water, N}, State) -> @@ -318,7 +318,7 @@ format_reason({function_clause, [MFA|_]}) -> format_reason({if_clause, [MFA|_]}) -> ["no true branch found while evaluating if expression in ", format_mfa(MFA)]; format_reason({{try_clause, Val}, [MFA|_]}) -> - ["no try clause matching ", print_val(Val), " in ", format_mfa(MFA)]; + ["no try clause matching ", print_val(Val), " in ", format_mfa(MFA)]; format_reason({badarith, [MFA|_]}) -> ["bad arithmetic expression in ", format_mfa(MFA)]; format_reason({{badmatch, Val}, [MFA|_]}) -> diff --git a/src/lager.app.src b/src/lager.app.src index c191b94..3ba8601 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -53,11 +53,13 @@ %% to async_threshold - async_threshold_window {async_threshold_window, 5}, %% <-- per sink {extra_sinks, [ - {audit, [{lager_file_backend, + {audit, + [{handlers, + [{lager_file_backend, [{file, "log/audit.log"}, {level, info}, {size, 10485760}, {date, "$D0"}, {count, 10}] } - ]} %% Security audit sink has no async behavior + ]}]} %% Security audit sink has no async behavior ]} ]} ]}. diff --git a/src/lager.erl b/src/lager.erl index c1e094d..21dff23 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -384,7 +384,7 @@ posix_error(Error) -> %% @private get_loglevels(Sink) -> - [gen_event:call(Handler, get_loglevel, infinity) || + [gen_event:call(Sink, Handler, get_loglevel, infinity) || Handler <- gen_event:which_handlers(Sink)]. %% @private @@ -401,7 +401,7 @@ add_trace_to_loglevel_config(Trace, Sink) -> %% @doc recalculate min log level update_loglevel_config(Sink) -> - {_, Traces} = lager_config:get({Sink, loglevel}), + {_, Traces} = lager_config:get({Sink, loglevel}, {ignore_me, []}), MinLog = minimum_loglevel(get_loglevels(Sink)), lager_config:set({Sink, loglevel}, {MinLog, Traces}). diff --git a/src/lager_app.erl b/src/lager_app.erl index ef3549d..f0eaa97 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -86,7 +86,7 @@ start_handlers(Sink, {ok, Handlers}) -> start_handler(Sink, Module, Config) -> {ok, Watcher} = supervisor:start_child(lager_handler_watcher_sup, [Sink, Module, Config]), - BackendId = Module:config_to_id(Config), + BackendId = maybe_make_handler_id(Module, Config), {BackendId, Watcher, Sink}. interpret_hwm(undefined) -> @@ -104,7 +104,7 @@ start_error_logger_handler({ok, false}, _HWM, _Whitelist) -> start_error_logger_handler(_, HWM, undefined) -> start_error_logger_handler(ignore_me, HWM, {ok, []}); start_error_logger_handler(_, HWM, {ok, WhiteList}) -> - case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HWM]]) of + case supervisor:start_child(lager_handler_watcher_sup, [?DEFAULT_SINK, error_logger_lager_h, [HWM]]) of {ok, _} -> [begin error_logger:delete_report_handler(X), X end || X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h | WhiteList]]; diff --git a/src/lager_backend_throttle.erl b/src/lager_backend_throttle.erl index 8b6f3ec..5c4f575 100644 --- a/src/lager_backend_throttle.erl +++ b/src/lager_backend_throttle.erl @@ -30,14 +30,15 @@ code_change/3]). -record(state, { + sink :: atom(), hwm :: non_neg_integer(), window_min :: non_neg_integer(), async = true :: boolean() }). -init([Hwm, Window]) -> - lager_config:set(async, true), - {ok, #state{hwm=Hwm, window_min=Hwm - Window}}. +init([{sink, Sink}, Hwm, Window]) -> + lager_config:set({Sink, async}, true), + {ok, #state{sink=Sink, hwm=Hwm, window_min=Hwm - Window}}. handle_call(get_loglevel, State) -> @@ -52,11 +53,11 @@ handle_event({log, _Message},State) -> case {Len > State#state.hwm, Len < State#state.window_min, State#state.async} of {true, _, true} -> %% need to flip to sync mode - lager_config:set(async, false), + lager_config:set({State#state.sink, async}, false), {ok, State#state{async=false}}; {_, true, false} -> %% need to flip to async mode - lager_config:set(async, true), + lager_config:set({State#state.sink, async}, true), {ok, State#state{async=true}}; _ -> %% nothing needs to change @@ -75,4 +76,3 @@ terminate(_Reason, _State) -> %% @private code_change(_OldVsn, State, _Extra) -> {ok, State}. - diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index 44cfd5a..4350cbd 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -72,10 +72,9 @@ init([Level,{Formatter,FormatterConfig}]) when is_atom(Formatter) -> _:_ -> {error, {fatal, bad_log_level}} end; -init(Level) -> +init([{sink, _Sink}, Level]) -> init([Level,{lager_default_formatter,?TERSE_FORMAT ++ [eol()]}]). - %% @private handle_call(get_loglevel, #state{level=Level} = State) -> {ok, Level, State}; diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 30439fe..94cdc14 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -80,6 +80,8 @@ {formatter_config, term()}. -spec init([option(),...]) -> {ok, #state{}} | {error, bad_config}. +init([{sink, _Sink}|Options]) -> + init(Options); init({FileName, LogLevel}) when is_list(FileName), is_atom(LogLevel) -> %% backwards compatability hack init([{file, FileName}, {level, LogLevel}]); @@ -237,7 +239,7 @@ do_write(#state{fd=FD, name=Name, flap=Flap} = State, Level, Msg) -> Flap end, State#state{flap=Flap2}; - _ -> + _ -> State end. @@ -711,7 +713,7 @@ filesystem_test_() -> {"tracing with options should work", fun() -> file:delete("foo.log"), - {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}], [{size, 20}, {check_interval, 1}]), + {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}], [{size, 20}, {check_interval, 1}]), lager:error("Test message"), ?assertNot(filelib:is_regular("foo.log.0")), lager:error("Test message"), @@ -809,4 +811,3 @@ config_validation_test_() -> -endif. - diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index 73722ac..35daec9 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -47,8 +47,11 @@ start_link(Sink, Module, Config) -> start(Sink, Module, Config) -> gen_server:start(?MODULE, [Sink, Module, Config], []). +init([Sink, Module, Config]) when is_list(Config) -> + install_handler(Sink, Module, [{sink, Sink}|Config]), + {ok, #state{sink=Sink, module=Module, config=Config}}; init([Sink, Module, Config]) -> - install_handler(Sink, Module, Config), + install_handler(Sink, Module, [{sink, Sink}]++[Config]), {ok, #state{sink=Sink, module=Module, config=Config}}. handle_call(_Call, _From, State) -> From 52c753c4f8bb74ce0eca8559ba7c20ed3879f922 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 23 Mar 2015 23:50:48 -0400 Subject: [PATCH 029/102] More bugfixes --- src/lager_app.erl | 1 + src/lager_config.erl | 13 ++++++++----- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index f0eaa97..1768796 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -118,6 +118,7 @@ wrap_proplist_value(Value) -> {ok, Value}. configure_sink(Sink, SinkDef) -> + lager_config:new_sink(Sink), determine_async_behavior(Sink, wrap_proplist_value( proplists:get_value(async_threshold, SinkDef)), diff --git a/src/lager_config.erl b/src/lager_config.erl index 962c387..253894f 100644 --- a/src/lager_config.erl +++ b/src/lager_config.erl @@ -20,7 +20,7 @@ -include("lager.hrl"). --export([new/0, get/1, get/2, set/2, +-export([new/0, new_sink/1, get/1, get/2, set/2, global_get/1, global_get/2, global_set/2]). -define(TBL, lager_config). @@ -40,14 +40,17 @@ new() -> error:badarg -> ?INT_LOG(warning, "Table ~p already exists", [?TBL]) end, - %% use insert_new here so that if we're in an appup we don't mess anything up - %% - %% until lager is completely started, allow all messages to go through - ets:insert_new(?TBL, {{?DEFAULT_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}}), + new_sink(?DEFAULT_SINK), %% Need to be able to find the `lager_handler_watcher' for all handlers ets:insert_new(?TBL, {{?GLOBAL, handlers}, []}), ok. +new_sink(Sink) -> + %% use insert_new here so that if we're in an appup we don't mess anything up + %% + %% until lager is completely started, allow all messages to go through + ets:insert_new(?TBL, {{Sink, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}}). + global_get(Key) -> global_get(Key, undefined). From 347c9c53b4c5119e4a322e2471b900d9bbe206d9 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 09:17:45 -0400 Subject: [PATCH 030/102] Lager STARTS --- src/lager_app.erl | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/lager_app.erl b/src/lager_app.erl index 1768796..347a24b 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -119,6 +119,12 @@ wrap_proplist_value(Value) -> configure_sink(Sink, SinkDef) -> lager_config:new_sink(Sink), + ChildId = list_to_atom(atom_to_list(Sink) ++ "_event"), + supervisor:start_child(lager_sup, + {ChildId, + {gen_event, start_link, + [{local, Sink}]}, + permanent, 5000, worker, [dynamic]}), determine_async_behavior(Sink, wrap_proplist_value( proplists:get_value(async_threshold, SinkDef)), From fb72c10ff05dea393234033db51da8da0027d3a8 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 16:08:15 -0400 Subject: [PATCH 031/102] Including the config in the handler ID only confuses our ability to detect matches from the handlers list --- src/lager_app.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 347a24b..abf41e1 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -86,7 +86,7 @@ start_handlers(Sink, {ok, Handlers}) -> start_handler(Sink, Module, Config) -> {ok, Watcher} = supervisor:start_child(lager_handler_watcher_sup, [Sink, Module, Config]), - BackendId = maybe_make_handler_id(Module, Config), + {BackendId, _Config} = maybe_make_handler_id(Module, Config), {BackendId, Watcher, Sink}. interpret_hwm(undefined) -> From 5f3f0fee6cd5d799afc1ba75240eea856fd15b26 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 16:09:00 -0400 Subject: [PATCH 032/102] Match the correct tuple. Return an {ok, _} tuple so the next case statement does not get confused --- src/lager.erl | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 21dff23..64a4ae9 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -187,7 +187,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, File}, 2, Handlers) of + Res = case lists:keyfind({lager_file_backend, File}, 1, Handlers) of false -> %% install the handler LogFileConfig = @@ -199,7 +199,8 @@ trace_file(File, Filter, Level, Options) -> HandlerInfo = lager_app:start_handler(Sink, lager_file_backend, LogFileConfig), - lager_config:global_set(handlers, [HandlerInfo|Handlers]); + lager_config:global_set(handlers, [HandlerInfo|Handlers]), + {ok, installed}; {_Watcher, _Handler, Sink} -> {ok, exists}; {_Watcher, _Handler, _OtherSink} -> From 564bf9824804aec9b41cf2bea83043eb11c38ab0 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 16:46:59 -0400 Subject: [PATCH 033/102] Do not lose existing handlers --- src/lager_app.erl | 1 + 1 file changed, 1 insertion(+) diff --git a/src/lager_app.erl b/src/lager_app.erl index abf41e1..c7bb8fa 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -77,6 +77,7 @@ start_handlers(_Sink, {ok, Handlers}) when not is_list(Handlers) -> start_handlers(Sink, {ok, Handlers}) -> %% handlers failing to start are handled in the handler_watcher lager_config:global_set(handlers, + lager_config:global_get(handlers, []) ++ lists:map(fun({Module, Config}) -> start_handler(Sink, Module, Config) end, From 67565b4444e16d2096d00bc48e61ed2208fc7472 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 17:37:25 -0400 Subject: [PATCH 034/102] Need 2ary get_loglevel (shame it is broken tho) --- src/lager.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index 64a4ae9..054e050 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -274,7 +274,7 @@ clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), _ = lager_util:trace_filter(none), lists:foreach(fun({_Watcher, Handler, Sink}) -> - case get_loglevel(Handler) of + case get_loglevel(Sink, Handler) of none -> gen_event:delete_handler(Sink, Handler, []); _ -> From a42eda8c966f6721cf644fb841aea9996272093c Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 24 Mar 2015 17:38:08 -0400 Subject: [PATCH 035/102] Misunderstood the inbound Module term. Should probably have specs and/or a different name. Actually represents the unique ID we want, e.g. {lager_file_handler, "foo.log"} --- src/lager_app.erl | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index c7bb8fa..4fc4d26 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -87,8 +87,7 @@ start_handlers(Sink, {ok, Handlers}) -> start_handler(Sink, Module, Config) -> {ok, Watcher} = supervisor:start_child(lager_handler_watcher_sup, [Sink, Module, Config]), - {BackendId, _Config} = maybe_make_handler_id(Module, Config), - {BackendId, Watcher, Sink}. + {Module, Watcher, Sink}. interpret_hwm(undefined) -> undefined; From 3ae2ca020c83beb7ab7ac03d235dc2d0cd73428b Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 27 Mar 2015 14:15:30 -0400 Subject: [PATCH 036/102] Mixed up application:get_env with proplists behavior --- src/lager_app.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 4fc4d26..ca26afb 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -70,11 +70,11 @@ determine_async_behavior(Sink, {ok, Threshold}, {ok, Window}) -> start_handlers(_Sink, undefined) -> ok; -start_handlers(_Sink, {ok, Handlers}) when not is_list(Handlers) -> +start_handlers(_Sink, Handlers) when not is_list(Handlers) -> error_logger:error_msg( "Invalid value for 'handlers' (must be list): ~p~n", [Handlers]), throw({error, bad_config}); -start_handlers(Sink, {ok, Handlers}) -> +start_handlers(Sink, Handlers) -> %% handlers failing to start are handled in the handler_watcher lager_config:global_set(handlers, lager_config:global_get(handlers, []) ++ @@ -151,7 +151,7 @@ start(_StartType, _StartArgs) -> application:get_env(lager, async_threshold), application:get_env(lager, async_threshold_window)), start_handlers(?DEFAULT_SINK, - application:get_env(lager, handlers, {ok, ?DEFAULT_HANDLER_CONF})), + application:get_env(lager, handlers, ?DEFAULT_HANDLER_CONF)), ok = add_configured_traces(), From 1b14a42b5ba8504abfb389ab15d06155dde577a9 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 27 Mar 2015 14:29:25 -0400 Subject: [PATCH 037/102] Follow-on to previous fix --- src/lager_app.erl | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index ca26afb..8558393 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -132,9 +132,7 @@ configure_sink(Sink, SinkDef) -> proplists:get_value(async_threshold_window, SinkDef)) ), start_handlers(Sink, - wrap_proplist_value( - proplists:get_value(handlers, SinkDef, [])) - ), + proplists:get_value(handlers, SinkDef, [])), lager:update_loglevel_config(Sink). From 4343bc776d6d57c3b6eb09534e8000ae5b6cc4a7 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 30 Mar 2015 09:24:47 -0400 Subject: [PATCH 038/102] Cannot use basho_bench without a parse transform; I hope this minimal change will do it --- src/lager_transform.erl | 1 + 1 file changed, 1 insertion(+) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index bf06b9a..b25ff33 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -180,6 +180,7 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager}, {integer, Line, SeverityAsInt}, {var, Line, LevelVar}, {var, Line, TracesVar}, + {atom, Line, lager_event}, {var, Line, PidVar} ] } From 087e931004d2782f280d3ed0c28f6a3faa03b9e1 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 30 Mar 2015 14:36:20 -0400 Subject: [PATCH 039/102] error_logger was always its own sink - return to that behavior --- src/lager_app.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 8558393..879a6a5 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -104,7 +104,7 @@ start_error_logger_handler({ok, false}, _HWM, _Whitelist) -> start_error_logger_handler(_, HWM, undefined) -> start_error_logger_handler(ignore_me, HWM, {ok, []}); start_error_logger_handler(_, HWM, {ok, WhiteList}) -> - case supervisor:start_child(lager_handler_watcher_sup, [?DEFAULT_SINK, error_logger_lager_h, [HWM]]) of + case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HWM]]) of {ok, _} -> [begin error_logger:delete_report_handler(X), X end || X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h | WhiteList]]; From 5c1a0795cfe8ea328e130c55efcc298c8755d208 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 30 Mar 2015 15:49:21 -0400 Subject: [PATCH 040/102] Need dat get_loglevels/4 --- src/lager.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index 054e050..4679704 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -29,7 +29,7 @@ md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, - get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/1, + get_loglevel/1, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, do_log/10, pr/2]). From b7da929f69f900c7f10255f82a39f562799bd087 Mon Sep 17 00:00:00 2001 From: MaximMinin Date: Wed, 15 Apr 2015 14:58:57 +0200 Subject: [PATCH 041/102] trace_file don't work, if env "log_root" is set. --- src/lager.erl | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index cfae17d..f617b0a 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -150,24 +150,25 @@ trace_file(File, Filter, Options) when is_list(Options) -> trace_file(File, Filter, debug, Options). trace_file(File, Filter, Level, Options) -> - Trace0 = {Filter, Level, {lager_file_backend, File}}, + FileName = lager_util:expand_path(File), + Trace0 = {Filter, Level, {lager_file_backend, FileName}}, case lager_util:validate_trace(Trace0) of {ok, Trace} -> Handlers = gen_event:which_handlers(lager_event), %% check if this file backend is already installed - Res = case lists:member({lager_file_backend, File}, Handlers) of + Res = case lists:member({lager_file_backend, FileName}, Handlers) of false -> %% install the handler - LogFileConfig = lists:keystore(level, 1, lists:keystore(file, 1, Options, {file, File}), {level, none}), + LogFileConfig = lists:keystore(level, 1, lists:keystore(file, 1, Options, {file, FileName}), {level, none}), supervisor:start_child(lager_handler_watcher_sup, - [lager_event, {lager_file_backend, File}, LogFileConfig]); + [lager_event, {lager_file_backend, FileName}, LogFileConfig]); _ -> {ok, exists} end, case Res of {ok, _} -> add_trace_to_loglevel_config(Trace), - {ok, {{lager_file_backend, File}, Filter, Level}}; + {ok, {{lager_file_backend, FileName}, Filter, Level}}; {error, _} = E -> E end; From 1f76822d1028f53f45f702726fe0870772856a24 Mon Sep 17 00:00:00 2001 From: Ted Burghart Date: Mon, 20 Apr 2015 16:07:16 -0400 Subject: [PATCH 042/102] Update rebar dependencies for OTP-17 development. Add/update file copyright headers where deterministically appropriate. Note: Many updates to rebar.config files have been scripted to ensure consistency and likely have re-ordered configuration settings and options. While the file may look significantly different, the content other than dependency updates (and, in some cases, more stringent compilation options) should be the same from rebar's perspective. --- rebar.config | 32 ++++++++++++++++++++++++++++---- 1 file changed, 28 insertions(+), 4 deletions(-) diff --git a/rebar.config b/rebar.config index 494a6ca..4d98bf3 100644 --- a/rebar.config +++ b/rebar.config @@ -1,9 +1,33 @@ -{erl_opts, [debug_info, warn_untyped_record]}. +%% -*- erlang -*- +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2011-2015 Basho Technologies, Inc. +%% +%% 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. +%% +%% ------------------------------------------------------------------- + {erl_first_files, ["src/lager_util.erl"]}. + +{erl_opts, [ + debug_info, + warn_untyped_record +]}. {deps, [ - {goldrush, "0\.1\.6", - {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.6"}}} - ]}. + {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {branch, "master"}}} +]}. {xref_checks, []}. {xref_queries, [{"(XC - UC) || (XU - X - B - lager_default_tracer : Mod - erlang:\"(is_map|map_size)\"/1 - maps:to_list/1)", []}]}. From 5f27739e1eb5a5ba24871d09bafa63ce4a52b9b9 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 20 Apr 2015 16:44:43 -0400 Subject: [PATCH 043/102] At the lowest level of the transform, allow multiple sinks --- src/lager_transform.erl | 255 ++++++++++++++++++++-------------------- 1 file changed, 128 insertions(+), 127 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index b25ff33..5ae5190 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -75,139 +75,140 @@ walk_clauses(Acc, [{clause, Line, Arguments, Guards, Body}|T]) -> walk_body(Acc, []) -> lists:reverse(Acc); walk_body(Acc, [H|T]) -> - walk_body([transform_statement(H)|Acc], T). + walk_body([transform_statement(H, [lager])|Acc], T). -transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager}, - {atom, _Line3, Severity}}, Arguments0} = Stmt) -> - case lists:member(Severity, ?LEVELS) of +transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, + {atom, _Line3, Function}}, Arguments0} = Stmt, + Sinks) -> + case lists:member(Module, Sinks) of true -> - SeverityAsInt=lager_util:level_to_num(Severity), - DefaultAttrs0 = {cons, Line, {tuple, Line, [ - {atom, Line, module}, {atom, Line, get(module)}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, function}, {atom, Line, get(function)}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, line}, - {integer, Line, Line}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, pid}, - {call, Line, {atom, Line, pid_to_list}, [ - {call, Line, {atom, Line ,self}, []}]}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, node}, - {call, Line, {atom, Line, node}, []}]}, - %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here - {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}}, - %{nil, Line}}}}}}}, - DefaultAttrs = case erlang:get(application) of - undefined -> - DefaultAttrs0; - App -> - %% stick the application in the attribute list - concat_lists({cons, Line, {tuple, Line, [ - {atom, Line, application}, - {atom, Line, App}]}, - {nil, Line}}, DefaultAttrs0) - end, - {Traces, Message, Arguments} = case Arguments0 of - [Format] -> - {DefaultAttrs, Format, {atom, Line, none}}; - [Arg1, Arg2] -> - %% some ambiguity here, figure out if these arguments are - %% [Format, Args] or [Attr, Format]. - %% The trace attributes will be a list of tuples, so check - %% for that. - case {element(1, Arg1), Arg1} of - {_, {cons, _, {tuple, _, _}, _}} -> - {concat_lists(Arg1, DefaultAttrs), - Arg2, {atom, Line, none}}; - {Type, _} when Type == var; - Type == lc; - Type == call; - Type == record_field -> - %% crap, its not a literal. look at the second - %% argument to see if it is a string - case Arg2 of - {string, _, _} -> - {concat_lists(Arg1, DefaultAttrs), - Arg2, {atom, Line, none}}; - _ -> - %% not a string, going to have to guess - %% it's the argument list - {DefaultAttrs, Arg1, Arg2} - end; - _ -> - {DefaultAttrs, Arg1, Arg2} - end; - [Attrs, Format, Args] -> - {concat_lists(Attrs, DefaultAttrs), Format, Args} - end, - %% Generate some unique variable names so we don't accidentaly export from case clauses. - %% Note that these are not actual atoms, but the AST treats variable names as atoms. - LevelVar = make_varname("__Level", Line), - TracesVar = make_varname("__Traces", Line), - PidVar = make_varname("__Pid", Line), - %% Wrap the call to lager_dispatch log in a case that will avoid doing any work if this message is not elegible for logging - %% case {whereis(lager_event(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of - {'case', Line, - {tuple, Line, - [{call, Line, {atom, Line, whereis}, [{atom, Line, lager_event}]}, - {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, - [ - %% {undefined, _} -> {error, lager_not_running} - {clause, Line, - [{tuple, Line, [{atom, Line, undefined}, {var, Line, '_'}]}], - [], - %% trick the linter into avoiding a 'term constructed by not used' error: - %% (fun() -> {error, lager_not_running} end)(); - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}]}, - %% If we care about the loglevel, or there's any traces installed, we have do more checking - %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> - {clause, Line, - [{tuple, Line, [{var, Line, PidVar}, {tuple, Line, [{var, Line, LevelVar}, {var, Line, TracesVar}]}]}], - [[{op, Line, 'orelse', - {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, - {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], - [ - %% do the call to lager:dispatch_log - {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, - [ - {atom,Line,Severity}, - Traces, - Message, - Arguments, - {integer, Line, get(truncation_size)}, - {integer, Line, SeverityAsInt}, - {var, Line, LevelVar}, - {var, Line, TracesVar}, - {atom, Line, lager_event}, - {var, Line, PidVar} - ] - } - ]}, - %% otherwise, do nothing - %% _ -> ok - {clause, Line, [{var, Line, '_'}],[],[{atom, Line, ok}]} - ]}; + case lists:member(Function, ?LEVELS) of + true -> + SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), + do_transform(Line, SinkName, Function, Arguments0); + false -> + Stmt + end; false -> - Stmt + list_to_tuple(transform_statement(tuple_to_list(Stmt), Sinks)) end; -transform_statement({call, Line, {remote, Line1, {atom, Line2, boston_lager}, - {atom, Line3, Severity}}, Arguments}) -> - NewArgs = case Arguments of - [{string, L, Msg}] -> [{string, L, re:replace(Msg, "r", "h", [{return, list}, global])}]; - [{string, L, Format}, Args] -> [{string, L, re:replace(Format, "r", "h", [{return, list}, global])}, Args]; - Other -> Other - end, - transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, - {atom, Line3, Severity}}, NewArgs}); -transform_statement(Stmt) when is_tuple(Stmt) -> - list_to_tuple(transform_statement(tuple_to_list(Stmt))); -transform_statement(Stmt) when is_list(Stmt) -> - [transform_statement(S) || S <- Stmt]; -transform_statement(Stmt) -> +transform_statement(Stmt, Sinks) when is_tuple(Stmt) -> + list_to_tuple(transform_statement(tuple_to_list(Stmt), Sinks)); +transform_statement(Stmt, Sinks) when is_list(Stmt) -> + [transform_statement(S, Sinks) || S <- Stmt]; +transform_statement(Stmt, _Sinks) -> Stmt. +do_transform(Line, SinkName, Severity, Arguments0) -> + SeverityAsInt=lager_util:level_to_num(Severity), + DefaultAttrs0 = {cons, Line, {tuple, Line, [ + {atom, Line, module}, {atom, Line, get(module)}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, function}, {atom, Line, get(function)}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, line}, + {integer, Line, Line}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, pid}, + {call, Line, {atom, Line, pid_to_list}, [ + {call, Line, {atom, Line ,self}, []}]}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, node}, + {call, Line, {atom, Line, node}, []}]}, + %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here + {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}}, + %{nil, Line}}}}}}}, + DefaultAttrs = case erlang:get(application) of + undefined -> + DefaultAttrs0; + App -> + %% stick the application in the attribute list + concat_lists({cons, Line, {tuple, Line, [ + {atom, Line, application}, + {atom, Line, App}]}, + {nil, Line}}, DefaultAttrs0) + end, + {Traces, Message, Arguments} = case Arguments0 of + [Format] -> + {DefaultAttrs, Format, {atom, Line, none}}; + [Arg1, Arg2] -> + %% some ambiguity here, figure out if these arguments are + %% [Format, Args] or [Attr, Format]. + %% The trace attributes will be a list of tuples, so check + %% for that. + case {element(1, Arg1), Arg1} of + {_, {cons, _, {tuple, _, _}, _}} -> + {concat_lists(Arg1, DefaultAttrs), + Arg2, {atom, Line, none}}; + {Type, _} when Type == var; + Type == lc; + Type == call; + Type == record_field -> + %% crap, its not a literal. look at the second + %% argument to see if it is a string + case Arg2 of + {string, _, _} -> + {concat_lists(Arg1, DefaultAttrs), + Arg2, {atom, Line, none}}; + _ -> + %% not a string, going to have to guess + %% it's the argument list + {DefaultAttrs, Arg1, Arg2} + end; + _ -> + {DefaultAttrs, Arg1, Arg2} + end; + [Attrs, Format, Args] -> + {concat_lists(Attrs, DefaultAttrs), Format, Args} + end, + %% Generate some unique variable names so we don't accidentaly export from case clauses. + %% Note that these are not actual atoms, but the AST treats variable names as atoms. + LevelVar = make_varname("__Level", Line), + TracesVar = make_varname("__Traces", Line), + PidVar = make_varname("__Pid", Line), + %% Wrap the call to lager_dispatch log in a case that will avoid doing any work if this message is not elegible for logging + %% case {whereis(lager_event(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of + {'case', Line, + {tuple, Line, + [{call, Line, {atom, Line, whereis}, [{atom, Line, SinkName}]}, + {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, + [ + %% {undefined, _} -> {error, lager_not_running} + {clause, Line, + [{tuple, Line, [{atom, Line, undefined}, {var, Line, '_'}]}], + [], + %% trick the linter into avoiding a 'term constructed by not used' error: + %% (fun() -> {error, lager_not_running} end)(); + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}]}, + %% If we care about the loglevel, or there's any traces installed, we have do more checking + %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> + {clause, Line, + [{tuple, Line, [{var, Line, PidVar}, {tuple, Line, [{var, Line, LevelVar}, {var, Line, TracesVar}]}]}], + [[{op, Line, 'orelse', + {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, + {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], + [ + %% do the call to lager:dispatch_log + {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, + [ + {atom,Line,Severity}, + Traces, + Message, + Arguments, + {integer, Line, get(truncation_size)}, + {integer, Line, SeverityAsInt}, + {var, Line, LevelVar}, + {var, Line, TracesVar}, + {atom, Line, SinkName}, + {var, Line, PidVar} + ] + } + ]}, + %% otherwise, do nothing + %% _ -> ok + {clause, Line, [{var, Line, '_'}],[],[{atom, Line, ok}]} + ]}. + make_varname(Prefix, Line) -> list_to_atom(Prefix ++ atom_to_list(get(module)) ++ integer_to_list(Line)). From 752065eb555d31cec887227cfe5cd6e105123ded Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 20 Apr 2015 16:47:39 -0400 Subject: [PATCH 044/102] Read extra sinks from configuration options --- src/lager_transform.erl | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 5ae5190..5661585 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -31,8 +31,10 @@ parse_transform(AST, Options) -> TruncSize = proplists:get_value(lager_truncation_size, Options, ?DEFAULT_TRUNCATION), Enable = proplists:get_value(lager_print_records_flag, Options, true), + Sinks = [lager] ++ proplists:get_value(lager_extra_sinks, Options, []), put(print_records_flag, Enable), put(truncation_size, TruncSize), + put(sinks, Sinks), erlang:put(records, []), %% .app file should either be in the outdir, or the same dir as the source file guess_application(proplists:get_value(outdir, Options), hd(AST)), @@ -75,7 +77,7 @@ walk_clauses(Acc, [{clause, Line, Arguments, Guards, Body}|T]) -> walk_body(Acc, []) -> lists:reverse(Acc); walk_body(Acc, [H|T]) -> - walk_body([transform_statement(H, [lager])|Acc], T). + walk_body([transform_statement(H, get(sinks))|Acc], T). transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, {atom, _Line3, Function}}, Arguments0} = Stmt, From 194f4aeb9426f4c4b09451213bd9b7db195c7625 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 21 Apr 2015 13:54:59 -0400 Subject: [PATCH 045/102] lager maps to lager_event, so audit maps to audit_event --- src/lager.app.src | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.app.src b/src/lager.app.src index 3ba8601..b36f639 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -53,7 +53,7 @@ %% to async_threshold - async_threshold_window {async_threshold_window, 5}, %% <-- per sink {extra_sinks, [ - {audit, + {audit_event, [{handlers, [{lager_file_backend, [{file, "log/audit.log"}, {level, info}, From e9fba0d64c99a10bd0c68af8b22546aa0d6a9934 Mon Sep 17 00:00:00 2001 From: Mikl Kurkov Date: Wed, 22 Apr 2015 15:26:12 +0300 Subject: [PATCH 046/102] Fix noproc test fail --- test/lager_test_backend.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 71b9de9..bc06788 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -651,7 +651,7 @@ error_logger_redirect_crash_test_() -> TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"), TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"), TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"), - TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"), + TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz) in gen_event:call1/3"), TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3") ] }. From 171e9596eacec79a33ae40749ff2072c48a1b6c7 Mon Sep 17 00:00:00 2001 From: Mikl Kurkov Date: Wed, 22 Apr 2015 15:49:38 +0300 Subject: [PATCH 047/102] Fix error_logger backend 'Format error' on unicode in Args --- src/error_logger_lager_h.erl | 6 +++--- test/lager_test_backend.erl | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 35 insertions(+), 3 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index ec0bfb2..6ce2bcc 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -197,7 +197,7 @@ log_event(Event, State) -> ?LOGFMT(error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]); _ -> ?CRASH_LOG(Event), - ?LOGMSG(error, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION)) + ?LOGFMT(error, Pid, Fmt, Args) end; {error_report, _GL, {Pid, std_error, D}} -> ?CRASH_LOG(Event), @@ -217,11 +217,11 @@ log_event(Event, State) -> ?CRASH_LOG(Event), ?LOGMSG(error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours)); {warning_msg, _GL, {Pid, Fmt, Args}} -> - ?LOGMSG(warning, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION)); + ?LOGFMT(warning, Pid, Fmt, Args); {warning_report, _GL, {Pid, std_warning, Report}} -> ?LOGMSG(warning, Pid, print_silly_list(Report)); {info_msg, _GL, {Pid, Fmt, Args}} -> - ?LOGMSG(info, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION)); + ?LOGFMT(info, Pid, Fmt, Args); {info_report, _GL, {Pid, std_info, D}} when is_list(D) -> Details = lists:sort(D), case Details of diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index bc06788..5904593 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -709,6 +709,17 @@ error_logger_redirect_test_() -> ?assertEqual(Expected, lists:flatten(Msg)) end }, + {"error messages with unicode characters in Args are printed", + fun() -> + sync_error_logger:error_msg("~ts", ["Привет!"]), + _ = gen_event:which_handlers(error_logger), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Привет!", lists:flatten(Msg)) + end + }, + {"error messages are truncated at 4096 characters", fun() -> sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), @@ -808,6 +819,27 @@ error_logger_redirect_test_() -> ?assert(length(lists:flatten(Msg)) < 5100) end }, + {"info messages with unicode characters in Args are printed", + fun() -> + sync_error_logger:info_msg("~ts", ["Привет!"]), + _ = gen_event:which_handlers(error_logger), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Привет!", lists:flatten(Msg)) + end + }, + {"warning messages with unicode characters in Args are printed", + fun() -> + sync_error_logger:warning_msg("~ts", ["Привет!"]), + Map = error_logger:warning_map(), + _ = gen_event:which_handlers(error_logger), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(Map),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Привет!", lists:flatten(Msg)) + end + }, {"warning messages are printed at the correct level", fun() -> From d66790f6124ef227e15e962fa89068d639032df4 Mon Sep 17 00:00:00 2001 From: MaximMinin Date: Thu, 23 Apr 2015 18:00:28 +0200 Subject: [PATCH 048/102] test for tracing to a dedicated file if root_log is set. --- src/lager_file_backend.erl | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index f5ab2c9..87c69e2 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -708,6 +708,20 @@ filesystem_test_() -> ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}])) end }, + {"tracing to a dedicated file should work even if root_log is set", + fun() -> + {ok, P} = file:get_cwd(), + file:delete(P ++ "/test_root_log/foo.log"), + application:set_env(lager, log_root, P++"/test_root_log"), + {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}]), + lager:error("Test message"), + %% not elegible for trace + lager:log(error, self(), "Test message"), + {ok, Bin3} = file:read_file(P++"/test_root_log/foo.log"), + application:unset_env(lager, log_root), + ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}])) + end + }, {"tracing with options should work", fun() -> file:delete("foo.log"), From a230240c58658b4a913903945653b53d066fccc0 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 09:30:46 -0400 Subject: [PATCH 049/102] Support new sink metadata in init --- test/lager_test_backend.erl | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 71b9de9..28e4343 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -32,6 +32,8 @@ -export([pop/0, count/0, count_ignored/0, flush/0, print_state/0]). -endif. +init([{sink, _Sink}, Level]) -> + init(Level); init(Level) -> {ok, #state{level=lager_util:config_to_mask(Level), buffer=[], ignored=[]}}. @@ -80,7 +82,7 @@ handle_event(_Event, State) -> handle_info(_Info, State) -> {ok, State}. -terminate(_Reason, _State) -> +terminate(Reason, State) -> ok. code_change(_OldVsn, State, _Extra) -> @@ -607,7 +609,7 @@ error_logger_redirect_crash_test_() -> ?assertEqual(Pid,proplists:get_value(pid,Metadata)), ?assertEqual(lager_util:level_to_num(error),Level) end - } + } end, {foreach, fun() -> @@ -1004,7 +1006,7 @@ error_logger_redirect_test_() -> ?assert(length(lists:flatten(Msg)) < 600) end }, - {"crash reports for 'special processes' should be handled right - function_clause", + {"crash reports for 'special processes' should be handled right - function_clause", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1017,7 +1019,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - case_clause", + {"crash reports for 'special processes' should be handled right - case_clause", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1030,7 +1032,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - exit", + {"crash reports for 'special processes' should be handled right - exit", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1043,7 +1045,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - error", + {"crash reports for 'special processes' should be handled right - error", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1268,5 +1270,3 @@ high_watermark_test_() -> }. -endif. - - From a71a7ff1a7ddabb59d36062b809224a0a9be9383 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 09:31:02 -0400 Subject: [PATCH 050/102] Do not forget to clear traces from global loglevel settings --- src/lager.erl | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/src/lager.erl b/src/lager.erl index 4679704..718adbd 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -270,8 +270,26 @@ stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> end, ok. +name_all_sinks() -> + sets:to_list( + lists:foldl(fun({_Watcher, _Handler, Sink}, Set) -> + sets:add_element(Sink, Set) + end, + sets:new(), + lager_config:global_get(handlers, []))). + +clear_traces_by_sink(Sinks) -> + lists:foreach(fun(S) -> + {Level, _Traces} = + lager_config:get({S, loglevel}), + lager_config:set({S, loglevel}, + {Level, []}) + end, + Sinks). + clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), + clear_traces_by_sink(name_all_sinks()), _ = lager_util:trace_filter(none), lists:foreach(fun({_Watcher, Handler, Sink}) -> case get_loglevel(Sink, Handler) of From daf3fdeb02822aec5f79f3a40c31eb11ffd72380 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 10:20:45 -0400 Subject: [PATCH 051/102] Move the extra sink argument down a layer so that reinstalls work properly --- src/lager_handler_watcher.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index 35daec9..6e8b739 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -48,10 +48,10 @@ start(Sink, Module, Config) -> gen_server:start(?MODULE, [Sink, Module, Config], []). init([Sink, Module, Config]) when is_list(Config) -> - install_handler(Sink, Module, [{sink, Sink}|Config]), + install_handler(Sink, Module, Config), {ok, #state{sink=Sink, module=Module, config=Config}}; init([Sink, Module, Config]) -> - install_handler(Sink, Module, [{sink, Sink}]++[Config]), + install_handler(Sink, Module, [Config]), {ok, #state{sink=Sink, module=Module, config=Config}}. handle_call(_Call, _From, State) -> @@ -92,7 +92,7 @@ code_change(_OldVsn, State, _Extra) -> %% internal install_handler(Sink, Module, Config) -> - case gen_event:add_sup_handler(Sink, Module, Config) of + case gen_event:add_sup_handler(Sink, Module, [{sink, Sink}|Config]) of ok -> ?INT_LOG(debug, "Lager installed handler ~p into ~p", [Module, Sink]), lager:update_loglevel_config(Sink), From f37a957a0e2fda9cc2fbd8ee206a4132aee3df70 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 10:21:49 -0400 Subject: [PATCH 052/102] Support extra sink argument --- test/lager_crash_backend.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/lager_crash_backend.erl b/test/lager_crash_backend.erl index b573a73..fa137f1 100644 --- a/test/lager_crash_backend.erl +++ b/test/lager_crash_backend.erl @@ -27,7 +27,7 @@ -include_lib("eunit/include/eunit.hrl"). -endif. -init([CrashBefore, CrashAfter]) -> +init([{sink, _Sink}, CrashBefore, CrashAfter]) -> case is_tuple(CrashBefore) andalso (timer:now_diff(CrashBefore, os:timestamp()) > 0) of true -> %?debugFmt("crashing!~n", []), From e0703482903f6d3be228ad1e72583c5e5db8f719 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 11:03:17 -0400 Subject: [PATCH 053/102] Fix some legacy loglevel handling in tests --- src/lager_console_backend.erl | 14 +++++++------- src/lager_file_backend.erl | 8 ++++---- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index 4350cbd..d7cf5b1 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -185,7 +185,7 @@ console_log_test_() -> register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), gen_event:add_handler(lager_event, lager_console_backend, info), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:log(info, self(), "Test message"), receive {io_request, From, ReplyAs, {put_chars, unicode, Msg}} -> @@ -205,7 +205,7 @@ console_log_test_() -> register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), gen_event:add_handler(lager_event, lager_console_backend, [info, true]), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:info("Test message"), PidStr = pid_to_list(self()), receive @@ -227,7 +227,7 @@ console_log_test_() -> gen_event:add_handler(lager_event, lager_console_backend, [info, {lager_default_formatter, [date,"#",time,"#",severity,"#",node,"#",pid,"#", module,"#",function,"#",file,"#",line,"#",message,"\r\n"]}]), - lager_config:set(loglevel, {?INFO, []}), + lager_config:set({lager_event, loglevel}, {?INFO, []}), lager:info("Test message"), PidStr = pid_to_list(self()), NodeStr = atom_to_list(node()), @@ -250,7 +250,7 @@ console_log_test_() -> register(user, Pid), gen_event:add_handler(lager_event, lager_console_backend, info), erlang:group_leader(Pid, whereis(lager_event)), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:debug("Test message"), receive {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} -> @@ -279,7 +279,7 @@ console_log_test_() -> unregister(user), register(user, Pid), gen_event:add_handler(lager_event, lager_console_backend, info), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), erlang:group_leader(Pid, whereis(lager_event)), lager:debug("Test message"), receive @@ -318,7 +318,7 @@ console_log_test_() -> unregister(user), register(user, Pid), gen_event:add_handler(lager_event, lager_console_backend, info), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '!=info'), erlang:group_leader(Pid, whereis(lager_event)), lager:debug("Test message"), @@ -349,7 +349,7 @@ console_log_test_() -> unregister(user), register(user, Pid), gen_event:add_handler(lager_event, lager_console_backend, info), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}), + lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '=debug'), erlang:group_leader(Pid, whereis(lager_event)), lager:debug("Test message"), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 94cdc14..8f6ff66 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -668,8 +668,8 @@ filesystem_test_() -> {"test.log", critical}), lager:error("Test message"), ?assertEqual({ok, <<>>}, file:read_file("test.log")), - {Level, _} = lager_config:get(loglevel), - lager_config:set(loglevel, {Level, [{[{module, + {Level, _} = lager_config:get({lager_event, loglevel}), + lager_config:set({lager_event, loglevel}, {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, "test.log"}}]}), lager:error("Test message"), @@ -686,8 +686,8 @@ filesystem_test_() -> {ok, Bin1} = file:read_file("test.log"), ?assertMatch([_, _, "[critical]", _, "Test message\n"], re:split(Bin1, " ", [{return, list}, {parts, 5}])), ok = file:delete("test.log"), - {Level, _} = lager_config:get(loglevel), - lager_config:set(loglevel, {Level, [{[{module, + {Level, _} = lager_config:get({lager_event, loglevel}), + lager_config:set({lager_event, loglevel}, {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, "test.log"}}]}), lager:critical("Test message"), From 9d9bf29633e9e6045ea4ee83f0766edefd1686e0 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 11:25:10 -0400 Subject: [PATCH 054/102] Fix init (for some questionable definition of fix) --- src/lager_console_backend.erl | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index d7cf5b1..eb563ba 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -38,6 +38,10 @@ -define(TERSE_FORMAT,[time, " ", color, "[", severity,"] ", message]). %% @private +init([Level]) when is_atom(Level) -> + init(Level); +init([{sink, _Sink}|T]) -> + init(T); init([Level, true]) -> % for backwards compatibility init([Level,{lager_default_formatter,[{eol, eol()}]}]); init([Level,false]) -> % for backwards compatibility @@ -72,7 +76,7 @@ init([Level,{Formatter,FormatterConfig}]) when is_atom(Formatter) -> _:_ -> {error, {fatal, bad_log_level}} end; -init([{sink, _Sink}, Level]) -> +init(Level) -> init([Level,{lager_default_formatter,?TERSE_FORMAT ++ [eol()]}]). %% @private @@ -184,7 +188,7 @@ console_log_test_() -> unregister(user), register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), - gen_event:add_handler(lager_event, lager_console_backend, info), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:log(info, self(), "Test message"), receive @@ -204,7 +208,7 @@ console_log_test_() -> unregister(user), register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), - gen_event:add_handler(lager_event, lager_console_backend, [info, true]), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info, true]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:info("Test message"), PidStr = pid_to_list(self()), @@ -225,7 +229,7 @@ console_log_test_() -> register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), gen_event:add_handler(lager_event, lager_console_backend, - [info, {lager_default_formatter, [date,"#",time,"#",severity,"#",node,"#",pid,"#", + [{sink, lager_event}, info, {lager_default_formatter, [date,"#",time,"#",severity,"#",node,"#",pid,"#", module,"#",function,"#",file,"#",line,"#",message,"\r\n"]}]), lager_config:set({lager_event, loglevel}, {?INFO, []}), lager:info("Test message"), @@ -248,7 +252,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, info), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), erlang:group_leader(Pid, whereis(lager_event)), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:debug("Test message"), @@ -278,7 +282,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, info), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), erlang:group_leader(Pid, whereis(lager_event)), lager:debug("Test message"), @@ -317,7 +321,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, info), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '!=info'), erlang:group_leader(Pid, whereis(lager_event)), @@ -348,7 +352,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, info), + gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '=debug'), erlang:group_leader(Pid, whereis(lager_event)), From 439a81c2ca058ce57aacf47fa04a16b46272c53b Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 11:41:41 -0400 Subject: [PATCH 055/102] Introduce sleep to account for interval between writes necessary for rotation to work --- src/lager_file_backend.erl | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 8f6ff66..4036381 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -716,6 +716,11 @@ filesystem_test_() -> {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}], [{size, 20}, {check_interval, 1}]), lager:error("Test message"), ?assertNot(filelib:is_regular("foo.log.0")), + %% rotation is sensitive to intervals between + %% writes so we sleep to exceed the 1 + %% millisecond interval specified by + %% check_interval above + timer:sleep(2), lager:error("Test message"), timer:sleep(10), ?assert(filelib:is_regular("foo.log.0")) From d5856f2284c4b0eca2e1b8ffd9a323d9e6111f66 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 11:47:05 -0400 Subject: [PATCH 056/102] Add sink identification export --- src/lager.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index 718adbd..f3afe2c 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -28,7 +28,7 @@ log/3, log/4, log/5, md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, - clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, + name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, get_loglevel/1, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, From 96f5b5c57dbe72ac7f56ce021e8949dc1c170846 Mon Sep 17 00:00:00 2001 From: Ted Burghart Date: Mon, 27 Apr 2015 12:24:27 -0400 Subject: [PATCH 057/102] changed has_line_numbers() to recognize the new OTP release pattern. --- test/lager_test_backend.erl | 30 +++++++++++++++++++++--------- 1 file changed, 21 insertions(+), 9 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 71b9de9..4b0bc92 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1,4 +1,6 @@ -%% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved. +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2011-2015 Basho Technologies, Inc. %% %% This file is provided to you under the Apache License, %% Version 2.0 (the "License"); you may not use this file @@ -13,6 +15,8 @@ %% KIND, either express or implied. See the License for the %% specific language governing permissions and limitations %% under the License. +%% +%% ------------------------------------------------------------------- -module(lager_test_backend). @@ -108,9 +112,17 @@ print_bad_state() -> has_line_numbers() -> %% are we R15 or greater - Rel = erlang:system_info(otp_release), - {match, [Major]} = re:run(Rel, "(?|(^R(\\d+)[A|B](|0(\\d)))|(^(\\d+)$))", [{capture, [2], list}]), - list_to_integer(Major) >= 15. + otp_version() >= 15. + +otp_version() -> + otp_version(erlang:system_info(otp_release)). + +otp_version([$R | Rel]) -> + {Ver, _} = string:to_integer(Rel), + Ver; +otp_version(Rel) -> + {Ver, _} = string:to_integer(Rel), + Ver. not_running_test() -> ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). @@ -607,7 +619,7 @@ error_logger_redirect_crash_test_() -> ?assertEqual(Pid,proplists:get_value(pid,Metadata)), ?assertEqual(lager_util:level_to_num(error),Level) end - } + } end, {foreach, fun() -> @@ -1004,7 +1016,7 @@ error_logger_redirect_test_() -> ?assert(length(lists:flatten(Msg)) < 600) end }, - {"crash reports for 'special processes' should be handled right - function_clause", + {"crash reports for 'special processes' should be handled right - function_clause", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1017,7 +1029,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - case_clause", + {"crash reports for 'special processes' should be handled right - case_clause", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1030,7 +1042,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - exit", + {"crash reports for 'special processes' should be handled right - exit", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), @@ -1043,7 +1055,7 @@ error_logger_redirect_test_() -> test_body(Expected, lists:flatten(Msg)) end }, - {"crash reports for 'special processes' should be handled right - error", + {"crash reports for 'special processes' should be handled right - error", fun() -> {ok, Pid} = special_process:start(), unlink(Pid), From 302767ec0f5ab15a1f36d4ad7c01214224689ddf Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 14:36:41 -0400 Subject: [PATCH 058/102] Make dialyzer happy --- src/lager_app.erl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 879a6a5..0ee0fde 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -120,11 +120,11 @@ wrap_proplist_value(Value) -> configure_sink(Sink, SinkDef) -> lager_config:new_sink(Sink), ChildId = list_to_atom(atom_to_list(Sink) ++ "_event"), - supervisor:start_child(lager_sup, - {ChildId, - {gen_event, start_link, - [{local, Sink}]}, - permanent, 5000, worker, [dynamic]}), + _ = supervisor:start_child(lager_sup, + {ChildId, + {gen_event, start_link, + [{local, Sink}]}, + permanent, 5000, worker, [dynamic]}), determine_async_behavior(Sink, wrap_proplist_value( proplists:get_value(async_threshold, SinkDef)), From e08fc432a8010e7f24d2323fe05f761bc39ca042 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Mon, 27 Apr 2015 17:11:24 -0400 Subject: [PATCH 059/102] Fix status --- src/lager.erl | 29 ++++++++++++++++++++--------- 1 file changed, 20 insertions(+), 9 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index f3afe2c..c4508b1 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -300,25 +300,36 @@ clear_all_traces() -> end end, Handlers). -%% XXX Needs heavy revision +find_traces(Sinks) -> + lists:foldl(fun(S, Acc) -> + {_Level, Traces} = lager_config:get({S, loglevel}), + Acc ++ lists:map(fun(T) -> {S, T} end, Traces) + end, + [], + Sinks). + status() -> Handlers = lager_config:global_get(handlers, []), - TraceCount = case length(element(2, lager_config:get(loglevel))) of + Sinks = lists:sort(name_all_sinks()), + Traces = find_traces(Sinks), + TraceCount = case length(Traces) of 0 -> 1; N -> N end, Status = ["Lager status:\n", [begin - Level = get_loglevel(Handler), + Level = get_loglevel(Sink, Handler), case Handler of {lager_file_backend, File} -> - io_lib:format("File ~s at level ~p\n", [File, Level]); + io_lib:format("File ~s (~s) at level ~p\n", [File, Sink, Level]); lager_console_backend -> - io_lib:format("Console at level ~p\n", [Level]); + io_lib:format("Console (~s) at level ~p\n", [Sink, Level]); _ -> [] end - end || Handler <- Handlers], + end || {Handler, _Watcher, Sink} <- lists:sort(fun({_, _, S1}, + {_, _, S2}) -> S1 =< S2 end, + Handlers)], "Active Traces:\n", [begin LevelName = case Level of @@ -330,9 +341,9 @@ status() -> Num -> lager_util:num_to_level(Num) end, - io_lib:format("Tracing messages matching ~p at level ~p to ~p\n", - [Filter, LevelName, Destination]) - end || {Filter, Level, Destination} <- element(2, lager_config:get(loglevel))], + io_lib:format("Tracing messages matching ~p (sink ~s) at level ~p to ~p\n", + [Filter, Sink, LevelName, Destination]) + end || {Sink, {Filter, Level, Destination}} <- Traces], [ "Tracing Reductions:\n", case ?DEFAULT_TRACER:info('query') of From 5b43a8bae45a8dffcc13d2485e4d31fc40512a0c Mon Sep 17 00:00:00 2001 From: Ted Burghart Date: Mon, 27 Apr 2015 18:10:22 -0400 Subject: [PATCH 060/102] Change how result strings are handled to accomodate additional data. --- test/lager_test_backend.erl | 54 ++++++++++++++++++++++++++++--------- 1 file changed, 42 insertions(+), 12 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 3caedae..822604d 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -114,7 +114,15 @@ print_bad_state() -> has_line_numbers() -> %% are we R15 or greater - otp_version() >= 15. + % this gets called a LOT - cache the answer + case erlang:get({?MODULE, has_line_numbers}) of + undefined -> + R = otp_version() >= 15, + erlang:put({?MODULE, has_line_numbers}, R), + R; + Bool -> + Bool + end. otp_version() -> otp_version(erlang:system_info(otp_release)). @@ -593,20 +601,42 @@ crash(Type) -> test_body(Expected, Actual) -> case has_line_numbers() of true -> - FileLine = string:substr(Actual, length(Expected)+1), - Body = string:substr(Actual, 1, length(Expected)), + ExLen = length(Expected), + {Body, Rest} = case length(Actual) > ExLen of + true -> + {string:substr(Actual, 1, ExLen), + string:substr(Actual, (ExLen + 1))}; + _ -> + {Actual, []} + end, ?assertEqual(Expected, Body), - case string:substr(FileLine, 1, 6) of + % OTP-17 (and maybe later releases) may tack on additional info + % about the failure, so if Actual starts with Expected (already + % confirmed by having gotten past assertEqual above) and ends + % with " line NNN" we can ignore what's in-between. By extension, + % since there may not be line information appended at all, any + % text we DO find is reportable, but not a test failure. + case Rest of [] -> - %% sometimes there's no line information... - ?assert(true); - " line " -> - ?assert(true); - Other -> - ?debugFmt("unexpected trailing data ~p", [Other]), - ?assert(false) + ok; + _ -> + % isolate the extra data and report it if it's not just + % a line number indicator + case re:run(Rest, "^.*( line \\d+)$", [{capture, [1]}]) of + nomatch -> + ?debugFmt( + "Trailing data \"~s\" following \"~s\"", + [Rest, Expected]); + {match, [{0, _}]} -> + % the whole sting is " line NNN" + ok; + {match, [{Off, _}]} -> + ?debugFmt( + "Trailing data \"~s\" following \"~s\"", + [string:substr(Rest, 1, Off), Expected]) + end end; - false -> + _ -> ?assertEqual(Expected, Actual) end. From 13ec782f0a380fa8123ee721ad2c86021165f725 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 28 Apr 2015 11:11:41 -0400 Subject: [PATCH 061/102] Fix the async threshold test to eliminate a race condition. It now tests something slightly different, but should be sufficient --- src/lager_backend_throttle.erl | 27 +++++++++++++++++++++++++++ test/lager_test_backend.erl | 23 +++++++++++++++++++---- 2 files changed, 46 insertions(+), 4 deletions(-) diff --git a/src/lager_backend_throttle.erl b/src/lager_backend_throttle.erl index 5c4f575..90b9c40 100644 --- a/src/lager_backend_throttle.erl +++ b/src/lager_backend_throttle.erl @@ -29,6 +29,17 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). +%% +%% Allow test code to verify that we're doing the needful. +-ifdef(TEST). +-define(ETS_TABLE, async_threshold_test). +-define(TOGGLE_SYNC(), test_increment(sync_toggled)). +-define(TOGGLE_ASYNC(), test_increment(async_toggled)). +-else. +-define(TOGGLE_SYNC(), true). +-define(TOGGLE_ASYNC(), true). +-endif. + -record(state, { sink :: atom(), hwm :: non_neg_integer(), @@ -53,10 +64,12 @@ handle_event({log, _Message},State) -> case {Len > State#state.hwm, Len < State#state.window_min, State#state.async} of {true, _, true} -> %% need to flip to sync mode + ?TOGGLE_SYNC(), lager_config:set({State#state.sink, async}, false), {ok, State#state{async=false}}; {_, true, false} -> %% need to flip to async mode + ?TOGGLE_ASYNC(), lager_config:set({State#state.sink, async}, true), {ok, State#state{async=true}}; _ -> @@ -76,3 +89,17 @@ terminate(_Reason, _State) -> %% @private code_change(_OldVsn, State, _Extra) -> {ok, State}. + +-ifdef(TEST). +test_get(Key) -> + get_default(ets:lookup(?ETS_TABLE, Key)). + +test_increment(Key) -> + ets:insert(?ETS_TABLE, + {Key, test_get(Key) + 1}). + +get_default([]) -> + 0; +get_default([{_Key, Value}]) -> + Value. +-endif. diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 28e4343..3e55a77 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -1161,6 +1161,9 @@ async_threshold_test_() -> {foreach, fun() -> error_logger:tty(false), + ets:new(async_threshold_test, [set, named_table, public]), + ets:insert_new(async_threshold_test, {sync_toggled, 0}), + ets:insert_new(async_threshold_test, {async_toggled, 0}), application:load(lager), application:set_env(lager, error_logger_redirect, false), application:set_env(lager, async_threshold, 2), @@ -1172,6 +1175,7 @@ async_threshold_test_() -> application:unset_env(lager, async_threshold), application:stop(lager), application:stop(goldrush), + ets:delete(async_threshold_test), error_logger:tty(true) end, [ @@ -1186,11 +1190,22 @@ async_threshold_test_() -> %% serialize on mailbox _ = gen_event:which_handlers(lager_event), timer:sleep(500), - %% there should be a ton of outstanding messages now, so async is false - ?assertEqual(false, lager_config:get(async)), - %% wait for all the workers to return, meaning that all the messages have been logged (since we're in sync mode) + + %% By now the flood of messages will have + %% forced the backend throttle to turn off + %% async mode, but it's possible all + %% outstanding requests have been processed, + %% so checking the current status (sync or + %% async) is an exercise in race control. + + %% Instead, we'll see whether the backend + %% throttle has toggled into sync mode at any + %% point in the past + ?assertMatch([{sync_toggled, N}] when N > 0, + ets:lookup(async_threshold_test, sync_toggled)), + %% wait for all the workers to return, meaning that all the messages have been logged (since we're definitely in sync mode at the end of the run) collect_workers(Workers), - %% serialize ont the mailbox again + %% serialize on the mailbox again _ = gen_event:which_handlers(lager_event), %% just in case... timer:sleep(1000), From 89ca81df2da25980187a47905e84fd5578dc4192 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Wed, 29 Apr 2015 10:13:26 -0400 Subject: [PATCH 062/102] Bugfix: handler tuple order was incorrect --- src/lager.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index c4508b1..70a30d7 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -291,7 +291,7 @@ clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), clear_traces_by_sink(name_all_sinks()), _ = lager_util:trace_filter(none), - lists:foreach(fun({_Watcher, Handler, Sink}) -> + lists:foreach(fun({Handler, _Watcher, Sink}) -> case get_loglevel(Sink, Handler) of none -> gen_event:delete_handler(Sink, Handler, []); From b0a2c4c82e3670287739510ba7ae069e78ee33cb Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Wed, 29 Apr 2015 10:45:32 -0400 Subject: [PATCH 063/102] More bugfixes re: trace file handling --- src/lager.erl | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 70a30d7..4d785bc 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -197,7 +197,7 @@ trace_file(File, Filter, Level, Options) -> {file, File}), {level, none}), HandlerInfo = - lager_app:start_handler(Sink, lager_file_backend, + lager_app:start_handler(Sink, {lager_file_backend, File}, LogFileConfig), lager_config:global_set(handlers, [HandlerInfo|Handlers]), {ok, installed}; @@ -291,14 +291,17 @@ clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), clear_traces_by_sink(name_all_sinks()), _ = lager_util:trace_filter(none), - lists:foreach(fun({Handler, _Watcher, Sink}) -> - case get_loglevel(Sink, Handler) of - none -> - gen_event:delete_handler(Sink, Handler, []); - _ -> - ok - end - end, Handlers). + lager_config:global_set(handlers, + lists:filter( + fun({Handler, _Watcher, Sink}) -> + case get_loglevel(Sink, Handler) of + none -> + gen_event:delete_handler(Sink, Handler, []), + false; + _ -> + true + end + end, Handlers)). find_traces(Sinks) -> lists:foldl(fun(S, Acc) -> From 066fa59a1c0b28b40e7481f61ddbaa3ca98bdd0a Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 1 May 2015 10:33:00 -0400 Subject: [PATCH 064/102] The audit sink was always for experimentation. Remove it before it accidentally slips into a release --- src/lager.app.src | 15 ++++----------- 1 file changed, 4 insertions(+), 11 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index b36f639..1936b93 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -48,18 +48,11 @@ %% How many messages per second to allow from error_logger before we start dropping them {error_logger_hwm, 50}, %% How big the gen_event mailbox can get before it is switched into sync mode - {async_threshold, 20}, %% <-- per sink + %% Can be reconfigured for extra sinks + {async_threshold, 20}, %% Switch back to async mode, when gen_event mailbox size decrease from `async_threshold' %% to async_threshold - async_threshold_window - {async_threshold_window, 5}, %% <-- per sink - {extra_sinks, [ - {audit_event, - [{handlers, - [{lager_file_backend, - [{file, "log/audit.log"}, {level, info}, - {size, 10485760}, {date, "$D0"}, {count, 10}] - } - ]}]} %% Security audit sink has no async behavior - ]} + %% Can be reconfigured for extra sinks + {async_threshold_window, 5} ]} ]}. From 96e3ba7095763f3d05681597d84468b79fd41f79 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 1 May 2015 10:40:32 -0400 Subject: [PATCH 065/102] More/fixed comments --- src/lager.app.src | 12 +++++++----- src/lager_app.erl | 5 +++++ 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/src/lager.app.src b/src/lager.app.src index 1936b93..6271b41 100644 --- a/src/lager.app.src +++ b/src/lager.app.src @@ -47,12 +47,14 @@ {error_logger_redirect, true}, %% How many messages per second to allow from error_logger before we start dropping them {error_logger_hwm, 50}, - %% How big the gen_event mailbox can get before it is switched into sync mode - %% Can be reconfigured for extra sinks + %% How big the gen_event mailbox can get before it is + %% switched into sync mode. This value only applies to + %% the default sink; extra sinks can supply their own. {async_threshold, 20}, - %% Switch back to async mode, when gen_event mailbox size decrease from `async_threshold' - %% to async_threshold - async_threshold_window - %% Can be reconfigured for extra sinks + %% Switch back to async mode, when gen_event mailbox size + %% decrease from `async_threshold' to async_threshold - + %% async_threshold_window. This value only applies to the + %% default sink; extra sinks can supply their own. {async_threshold_window, 5} ]} ]}. diff --git a/src/lager_app.erl b/src/lager_app.erl index 0ee0fde..426ed51 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -112,6 +112,11 @@ start_error_logger_handler(_, HWM, {ok, WhiteList}) -> [] end. +%% `determine_async_behavior/3' is called with the results from either +%% `application:get_env/2' and `proplists:get_value/2'. Since +%% `application:get_env/2' wraps a successful retrieval in an `{ok, +%% Value}' tuple, do the same for the result from +%% `proplists:get_value/2'. wrap_proplist_value(undefined) -> undefined; wrap_proplist_value(Value) -> From 4da506b06bd61ae2ce6e2af7f70c6bd4d7dfacd0 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 1 May 2015 10:51:29 -0500 Subject: [PATCH 066/102] Add check for same file across backends. Throw {error, bad_config} if we find one during handler startup. --- src/lager_app.erl | 40 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/src/lager_app.erl b/src/lager_app.erl index 0ee0fde..0c3482b 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -30,6 +30,7 @@ start_handler/3, stop/1]). +-define(FILENAMES, '__lager_file_backend_filenames'). -define(THROTTLE, lager_backend_throttle). -define(DEFAULT_HANDLER_CONF, [{lager_console_backend, info}, @@ -79,6 +80,7 @@ start_handlers(Sink, Handlers) -> lager_config:global_set(handlers, lager_config:global_get(handlers, []) ++ lists:map(fun({Module, Config}) -> + check_handler_config(Module, Config), start_handler(Sink, Module, Config) end, expand_handlers(Handlers))), @@ -89,6 +91,28 @@ start_handler(Sink, Module, Config) -> [Sink, Module, Config]), {Module, Watcher, Sink}. +check_handler_config({lager_file_backend, F}, _Config) -> + Fs = case get(?FILENAMES) of + undefined -> ordsets:new(); + X -> X + end, + case ordsets:is_element(F, Fs) of + true -> + error_logger:error_msg( + "Cannot have same file (~p) in multiple file backends~n", [F]), + throw({error, bad_config}); + false -> + put(?FILENAMES, + ordsets:add_element(F, Fs)) + end, + ok; + +check_handler_config(_Other, _Config) -> + ok. + +clean_up_config_checks() -> + erase(?FILENAMES). + interpret_hwm(undefined) -> undefined; interpret_hwm({ok, undefined}) -> @@ -166,6 +190,8 @@ start(_StartType, _StartArgs) -> %% Now handle extra sinks configure_extra_sinks(application:get_env(lager, extra_sinks, [])), + clean_up_config_checks(), + {ok, Pid, SavedHandlers}. @@ -280,4 +306,18 @@ application_config_mangling_test_() -> ) } ]. + +check_handler_config_test_() -> + Good = expand_handlers(?DEFAULT_HANDLER_CONF), + Bad = expand_handlers([{lager_console_backend, info}, + {lager_file_backend, [{file, "same_file.log"}]}, + {lager_file_backend, [{file, "same_file.log"}, {level, info}]}]), + [ + {"lager_file_backend_good", + ?_assertEqual([ok, ok, ok], [ check_handler_config(M,C) || {M,C} <- Good ]) + }, + {"lager_file_backend_bad", + ?_assertThrow({error, bad_config}, [ check_handler_config(M,C) || {M,C} <- Bad ]) + } + ]. -endif. From 566a6dc626456c6bc1e516b3af518b3113fa43a7 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 1 May 2015 14:49:27 -0500 Subject: [PATCH 067/102] If Sink referenced but not running, return error If a sink is referenced in a call, but is not configured (by being a running process), then emit an {error, {sink_not_configured, Sink}} tuple. --- src/lager.erl | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 4d785bc..426ee21 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -86,13 +86,18 @@ md(_) -> dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). --spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running}. +-spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running} | {error, {sink_not_configured, term()}}. %% this is the same check that the parse transform bakes into the module at compile time dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> SeverityAsInt=lager_util:level_to_num(Severity), case {whereis(Sink), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of {undefined, _} -> - {error, lager_not_running}; + case whereis(lager_event) of + false -> + {error, lager_not_running}; + true -> + {error, {sink_not_configured, Sink}} + end; {SinkPid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); _ -> @@ -117,7 +122,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr end, LagerMsg = lager_msg:new(Msg, Severity, Metadata, Destinations), - case lager_config:get({Sink, async}, false) of %% this needs to be able to get value from a non-default sink + case lager_config:get({Sink, async}, false) of true -> gen_event:notify(SinkPid, {log, LagerMsg}); false -> From aa195121e7b1b10eb6928532401d2ff343dd6512 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 1 May 2015 14:51:46 -0500 Subject: [PATCH 068/102] Get loglevel of sink not default in transform Previously, code would only look up the default sink's loglevel, not the referenced sink name's loglevel. In other words, if lager_event's loglevel was set to NONE, it squelch all events from all sinks, and conversely if a sink's loglevel was set to NONE, it would be silently ignored. --- src/lager_transform.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 5661585..637917e 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -169,11 +169,11 @@ do_transform(Line, SinkName, Severity, Arguments0) -> TracesVar = make_varname("__Traces", Line), PidVar = make_varname("__Pid", Line), %% Wrap the call to lager_dispatch log in a case that will avoid doing any work if this message is not elegible for logging - %% case {whereis(lager_event(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of + %% case {whereis(Sink), lager_config:get(Sink, loglevel, {?LOG_NONE, []})} of {'case', Line, {tuple, Line, [{call, Line, {atom, Line, whereis}, [{atom, Line, SinkName}]}, - {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, + {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, SinkName}, {atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, [ %% {undefined, _} -> {error, lager_not_running} {clause, Line, @@ -190,7 +190,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], [ - %% do the call to lager:dispatch_log + %% do the call to lager:dispatch_log/9 {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, [ {atom,Line,Severity}, From d5e78433875d9d3b6799a76a4080bfb00b05aebc Mon Sep 17 00:00:00 2001 From: Pedram Nimreezi Date: Mon, 4 May 2015 07:20:21 -0400 Subject: [PATCH 069/102] Add support for group leader strategies The default strategy is 'handle', for backwards compatibility, and is set to that if otherwise undefined. Other strategies include 'mirror' and 'ignore'. Before when the error_logger was removed when lager starts up, some functionality was chopped off, such as forwarding io to the caller's group leader, this is supported with the strategy 'ignore' and is similar to how the io system in erlang works traditionally. Setting the 'mirror' strategy will essentially combine the other two strategies such that the remote node reply is forwarded and also handled locally. This is in some cases more in-line with what some people might expect, efficiency may vary. The traditional 'ignore' approach is more suitable and most likely originally intended for embedded terminals where 'mirror'-ing the io is largely unnecessary. --- src/error_logger_lager_h.erl | 21 +++++++++++++++++---- src/lager_app.erl | 17 ++++++++++++++++- 2 files changed, 33 insertions(+), 5 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index ec0bfb2..a570e2e 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -41,7 +41,9 @@ %% the current second lasttime = os:timestamp() :: erlang:timestamp(), %% count of dropped messages this second - dropped = 0 :: non_neg_integer() + dropped = 0 :: non_neg_integer(), + %% group leader strategy + groupleader_strategy :: handle | ignore | mirror }). -define(LOGMSG(Level, Pid, Msg), @@ -74,16 +76,27 @@ set_high_water(N) -> gen_event:call(error_logger, ?MODULE, {set_high_water, N}, infinity). -spec init(any()) -> {ok, #state{}}. -init([HighWaterMark]) -> - {ok, #state{hwm=HighWaterMark}}. +init([HighWaterMark, GlStrategy]) -> + {ok, #state{hwm=HighWaterMark, groupleader_strategy=GlStrategy}}. handle_call({set_high_water, N}, State) -> {ok, ok, State#state{hwm = N}}; handle_call(_Request, State) -> {ok, unknown_call, State}. -handle_event(Event, State) -> +handle_event(Event, #state{groupleader_strategy=GlStrategy0}=State) -> case check_hwm(State) of + {true, NewState} when is_pid(element(2, Event)) -> + case element(2, Event) of + GL when node(GL) =/= node(), GlStrategy0 =:= ignore -> + gen_event:notify({error_logger, node(GL)}, Event), + {ok, State}; + GL when node(GL) =/= node(), GlStrategy0 =:= mirror -> + gen_event:notify({error_logger, node(GL)}, Event), + log_event(Event, NewState); + _ -> + log_event(Event, NewState) + end; {true, NewState} -> log_event(Event, NewState); {false, NewState} -> diff --git a/src/lager_app.erl b/src/lager_app.erl index 6364aef..c10ec2b 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -104,7 +104,22 @@ start(_StartType, _StartArgs) -> WhiteList0 end, - case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HighWaterMark]]) of + GlStrategy = case application:get_env(lager, error_logger_groupleader_strategy) of + undefined -> + handle; + {ok, GlStrategy0} when + GlStrategy0 =:= handle; + GlStrategy0 =:= ignore; + GlStrategy0 =:= mirror -> + GlStrategy0; + {ok, BadGlStrategy} -> + error_logger:error_msg( + "Invalid value for 'error_logger_groupleader_strategy': ~p~n", + [BadGlStrategy]), + throw({error, bad_config}) + end, + + case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HighWaterMark, GlStrategy]]) of {ok, _} -> [begin error_logger:delete_report_handler(X), X end || X <- gen_event:which_handlers(error_logger) -- [error_logger_lager_h | WhiteList]]; From c4e2520665b9f5a4c9606016a83f07551f055bb4 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 6 May 2015 22:28:41 -0500 Subject: [PATCH 070/102] Fix derpy case clause with whereis --- src/lager.erl | 4 ++-- src/lager_transform.erl | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 426ee21..d21a7a1 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -93,9 +93,9 @@ dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity case {whereis(Sink), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of {undefined, _} -> case whereis(lager_event) of - false -> + undefined -> {error, lager_not_running}; - true -> + _Pid -> {error, {sink_not_configured, Sink}} end; {SinkPid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 637917e..19ab6ab 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -173,7 +173,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {'case', Line, {tuple, Line, [{call, Line, {atom, Line, whereis}, [{atom, Line, SinkName}]}, - {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, SinkName}, {atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, + {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{tuple, Line, [{atom, Line, SinkName}, {atom, Line, loglevel}]}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, [ %% {undefined, _} -> {error, lager_not_running} {clause, Line, From f233b6d342342bc0cb182401571df8f661108252 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 6 May 2015 23:02:54 -0500 Subject: [PATCH 071/102] Return sinkname when not configured from transform --- src/lager_transform.erl | 22 ++++++++++++++++++---- 1 file changed, 18 insertions(+), 4 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 19ab6ab..f372d15 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -175,13 +175,27 @@ do_transform(Line, SinkName, Severity, Arguments0) -> [{call, Line, {atom, Line, whereis}, [{atom, Line, SinkName}]}, {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{tuple, Line, [{atom, Line, SinkName}, {atom, Line, loglevel}]}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, [ - %% {undefined, _} -> {error, lager_not_running} + %% {undefined, _} -> {clause, Line, [{tuple, Line, [{atom, Line, undefined}, {var, Line, '_'}]}], [], - %% trick the linter into avoiding a 'term constructed by not used' error: - %% (fun() -> {error, lager_not_running} end)(); - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}]}, + {'case', Line, %% case whereis(lager_event) of + {call, Line, {atom, Line, whereis}, [{atom, Line, lager_event}]}, + [{clause, Line, % undefined -> {error, lager_not_running}; + [{atom, Line, undefined}], + [], + %% trick the linter into avoiding a 'term constructed by not used' error: + %% (fun() -> {error, lager_not_running} end)(); + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}] + }, + {clause, Line, % _ -> + [{var, Line, '_'}], + [], + %% same trick + %% (fun() -> {error, {sink_not_configured, SinkName}} end)(); + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error}, [{tuple, Line, [{atom, Line, lager_not_running}, {atom, Line, SinkName}]}]]}]}]}}}], [] + }] + }}, %% If we care about the loglevel, or there's any traces installed, we have do more checking %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> {clause, Line, From 31f560556012658577ba5e86ec00c38b3decb988 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 6 May 2015 23:13:19 -0500 Subject: [PATCH 072/102] Add multiple sink documentation --- README.md | 60 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/README.md b/README.md index 7168de1..cdbc2ab 100644 --- a/README.md +++ b/README.md @@ -16,6 +16,7 @@ Features * When no handler is consuming a log level (eg. debug) no event is sent to the log handler * Supports multiple backends, including console and file. +* Supports multiple sinks (and eventually different sync/async policies per sink) * Rewrites common OTP error messages into more readable messages * Support for pretty printing records encountered at compile time * Tolerant in the face of large or many log messages, won't out of memory the node @@ -92,6 +93,65 @@ your app.config): The available configuration options for each backend are listed in their module's documentation. +Multiple sinks +-------------- +Previously, lager supported a single sink `lager_event`. Lager can now support +additional sinks with their own backend configurations. Eventually, the goal is +to support different latency and sync/async message policies. (For example, if +there were an `audit` sink, we might be willing to pay the latency costs to log +all of those messages to disk and we don't want lager to drop them in an +overload scenario.) + +To use multiple sinks (beyond the built in sink of lager and lager_event), you +need to: + +1. Setup rebar.config +2. Configure the backends in app.config + +### rebar.config + +In `rebar.config` for the containing project, include this tuple in `erl_opts`: + +`{lager_extra_sinks, [sink1, sink2, sink3]}` + +### Runtime requirements + +Sinks must be configured with backends (and possibly in the future behavioral differences). + + app.config + +```erlang +[{lager, [ + {log_root, "/tmp"}, + + %% Default handlers for lager/lager_event + {handlers, [ + {lager_console_backend, info}, + {lager_file_backend, [{file, "error.log"}, {level, error}]}, + {lager_file_backend, [{file, "console.log"}, {level, info}]} + ]}, + + %% Any other sinks + {extra_sinks, + [ + {sink1_event, + [{handlers, + [{lager_file_backend, + [{file, "sink1.log"}, + {level, info} + ] + }] + }] + }] + } + ] + } +]. +``` + +In your application you can then use `sink1:info(...)` as you normally would, but the message +will be routed into the sink handler(s) instead of the default `lager_event` handler. + Custom Formatting ----------------- All loggers have a default formatting that can be overriden. A formatter is any module that From 8a178613e37403a59aa9b7c68e2fc63d29f42a9c Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 8 May 2015 15:53:03 -0500 Subject: [PATCH 073/102] Fix errors in dispatch_log/6 parse transform Originally I tried to bodge in a handcoded parse transform and it did not go very well. This time, we simplify the case statement in lager.erl and use this simplified version in the parse transform after getting the AST from the Erlang compiler. --- src/lager.erl | 19 +++---- src/lager_transform.erl | 106 +++++++++++++++++++--------------------- 2 files changed, 57 insertions(+), 68 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index d21a7a1..cfbc303 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -86,22 +86,17 @@ md(_) -> dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). --spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running} | {error, {sink_not_configured, term()}}. +-spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}. %% this is the same check that the parse transform bakes into the module at compile time +%% see lager_transform (lines 173-216) dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> SeverityAsInt=lager_util:level_to_num(Severity), - case {whereis(Sink), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of - {undefined, _} -> - case whereis(lager_event) of - undefined -> - {error, lager_not_running}; - _Pid -> - {error, {sink_not_configured, Sink}} - end; - {SinkPid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> + case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of + {undefined, undefined, _} -> {error, lager_not_running}; + {undefined, _LagerEventPid0, _} -> {error, {sink_not_configured, Sink}}; + {SinkPid, _LagerEventPid1, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); - _ -> - ok + _ -> ok end. %% @private Should only be called externally from code generated from the parse transform diff --git a/src/lager_transform.erl b/src/lager_transform.erl index f372d15..1546c04 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -168,62 +168,56 @@ do_transform(Line, SinkName, Severity, Arguments0) -> LevelVar = make_varname("__Level", Line), TracesVar = make_varname("__Traces", Line), PidVar = make_varname("__Pid", Line), - %% Wrap the call to lager_dispatch log in a case that will avoid doing any work if this message is not elegible for logging - %% case {whereis(Sink), lager_config:get(Sink, loglevel, {?LOG_NONE, []})} of - {'case', Line, - {tuple, Line, - [{call, Line, {atom, Line, whereis}, [{atom, Line, SinkName}]}, - {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{tuple, Line, [{atom, Line, SinkName}, {atom, Line, loglevel}]}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]}, - [ - %% {undefined, _} -> - {clause, Line, - [{tuple, Line, [{atom, Line, undefined}, {var, Line, '_'}]}], - [], - {'case', Line, %% case whereis(lager_event) of - {call, Line, {atom, Line, whereis}, [{atom, Line, lager_event}]}, - [{clause, Line, % undefined -> {error, lager_not_running}; - [{atom, Line, undefined}], - [], - %% trick the linter into avoiding a 'term constructed by not used' error: - %% (fun() -> {error, lager_not_running} end)(); - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}] - }, - {clause, Line, % _ -> - [{var, Line, '_'}], - [], - %% same trick - %% (fun() -> {error, {sink_not_configured, SinkName}} end)(); - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error}, [{tuple, Line, [{atom, Line, lager_not_running}, {atom, Line, SinkName}]}]]}]}]}}}], [] - }] - }}, - %% If we care about the loglevel, or there's any traces installed, we have do more checking - %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> - {clause, Line, - [{tuple, Line, [{var, Line, PidVar}, {tuple, Line, [{var, Line, LevelVar}, {var, Line, TracesVar}]}]}], - [[{op, Line, 'orelse', - {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, - {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], - [ - %% do the call to lager:dispatch_log/9 - {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, - [ - {atom,Line,Severity}, - Traces, - Message, - Arguments, - {integer, Line, get(truncation_size)}, - {integer, Line, SeverityAsInt}, - {var, Line, LevelVar}, - {var, Line, TracesVar}, - {atom, Line, SinkName}, - {var, Line, PidVar} - ] - } - ]}, - %% otherwise, do nothing - %% _ -> ok - {clause, Line, [{var, Line, '_'}],[],[{atom, Line, ok}]} - ]}. + %% Wrap the call to lager:dispatch_log/6 in case that will avoid doing any work if this message is not elegible for logging + %% See lager.erl (lines 89-100) for lager:dispatch_log/6 + %% case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of + {'case',Line, + {tuple,Line, + [{call,Line,{atom,Line,whereis},[{atom,Line,SinkName}]}, + {call,Line,{atom,Line,whereis},[{atom,Line,lager_event}]}, %% <--lager_event is ?DEFAULT_SINK + {call,Line, + {remote,Line,{atom,Line,lager_config},{atom,Line,get}}, + [{tuple,Line,[{atom,Line,SinkName},{atom,Line,loglevel}]}, + {tuple,Line,[{integer,Line,0},{nil,1}]}]}]}, + %% {undefined, undefined, _} -> {error, lager_not_running}; + [{clause,Line, + [{tuple,Line, + [{atom,Line,undefined},{atom,Line,undefined},{var,Line,'_'}]}], + [], + %% trick the linter into avoiding a 'term constructed but not used' error: + %% (fun() -> {error, lager_not_running} end)() + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}] + }, + %% {undefined, _, _} -> {error, {sink_not_configured, Sink}}; + {clause,Line, + [{tuple,Line, + [{atom,Line,undefined},{var,Line,'_'},{var,Line,'_'}]}], + [], + %% same trick as above to avoid linter error + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple,Line, [{atom,Line,error}, {tuple,Line,[{atom,Line,sink_not_configured},{atom,Line,SinkName}]}]}]}]}}, []}] + }, + %% {SinkPid, _, {Level, Traces}} when ... -> lager:do_log/9; + {clause,Line, + [{tuple,Line, + [{var,Line,PidVar}, + {var,Line,'_'}, + {tuple,Line,[{var,Line,LevelVar},{var,Line,TracesVar}]}]}], + [[{op, Line, 'orelse', + {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, + {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], + [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, + [{atom,Line,Severity}, + Traces, + Message, + Arguments, + {integer, Line, get(truncation_size)}, + {integer, Line, SeverityAsInt}, + {var, Line, LevelVar}, + {var, Line, TracesVar}, + {atom, Line, SinkName}, + {var, Line, PidVar}]}]}, + %% _ -> ok + {clause,Line,[{var,Line,'_'}],[],[{atom,Line,ok}]}]}. make_varname(Prefix, Line) -> list_to_atom(Prefix ++ atom_to_list(get(module)) ++ integer_to_list(Line)). From 6936bbc772eb4d3c58466eb3db83a34677a852d9 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 12 May 2015 17:36:48 -0500 Subject: [PATCH 074/102] Add __lager_test_sink to rebar.config --- rebar.config | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rebar.config b/rebar.config index 494a6ca..88b3797 100644 --- a/rebar.config +++ b/rebar.config @@ -1,4 +1,4 @@ -{erl_opts, [debug_info, warn_untyped_record]}. +{erl_opts, [{lager_extra_sinks, ['__lager_test_sink']}, debug_info, warn_untyped_record]}. {erl_first_files, ["src/lager_util.erl"]}. {deps, [ {goldrush, "0\.1\.6", From 84cc6322ec9b287fb139bd09374b7e13b3cf2e29 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 12 May 2015 17:37:07 -0500 Subject: [PATCH 075/102] Add tests for multiple sinks --- test/lager_test_backend.erl | 141 +++++++++++++++++++++++++++++++++--- 1 file changed, 131 insertions(+), 10 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 3e55a77..459f8ed 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -23,12 +23,16 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). --record(state, {level, buffer, ignored}). --record(test, {attrs, format, args}). --compile([{parse_transform, lager_transform}]). +-define(TEST_SINK, '__lager_test_sink'). +-define(TEST_SINK_H, '__lager_test_sink_event'). + +-record(state, {level :: list(), buffer :: list(), ignored :: term()}). +-compile({parse_transform, lager_transform}). +%-compile([{parse_transform, lager_transform}]). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). +-record(test, {attrs :: list(), format :: list(), args :: list()}). -export([pop/0, count/0, count_ignored/0, flush/0, print_state/0]). -endif. @@ -82,7 +86,7 @@ handle_event(_Event, State) -> handle_info(_Info, State) -> {ok, State}. -terminate(Reason, State) -> +terminate(_Reason, _State) -> ok. code_change(_OldVsn, State, _Extra) -> @@ -91,22 +95,41 @@ code_change(_OldVsn, State, _Extra) -> -ifdef(TEST). pop() -> - gen_event:call(lager_event, ?MODULE, pop). + pop(lager_event). count() -> - gen_event:call(lager_event, ?MODULE, count). + count(lager_event). count_ignored() -> - gen_event:call(lager_event, ?MODULE, count_ignored). + count_ignored(lager_event). flush() -> - gen_event:call(lager_event, ?MODULE, flush). + flush(lager_event). print_state() -> - gen_event:call(lager_event, ?MODULE, print_state). + print_state(lager_event). print_bad_state() -> - gen_event:call(lager_event, ?MODULE, print_bad_state). + print_bad_state(lager_event). + +pop(Sink) -> + gen_event:call(Sink, ?MODULE, pop). + +count(Sink) -> + gen_event:call(Sink, ?MODULE, count). + +count_ignored(Sink) -> + gen_event:call(Sink, ?MODULE, count_ignored). + +flush(Sink) -> + gen_event:call(Sink, ?MODULE, flush). + +print_state(Sink) -> + gen_event:call(Sink, ?MODULE, print_state). + +print_bad_state(Sink) -> + gen_event:call(Sink, ?MODULE, print_bad_state). + has_line_numbers() -> %% are we R15 or greater @@ -128,6 +151,11 @@ lager_test_() -> ?assertEqual(0, count()) end }, + {"test sink not running", + fun() -> + ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) + end + }, {"logging works", fun() -> lager:warning("test message"), @@ -558,6 +586,99 @@ lager_test_() -> ] }. +extra_sinks_test_() -> + {foreach, + fun setup_sink/0, + fun cleanup/1, + [ + {"observe that there is nothing up my sleeve", + fun() -> + ?assertEqual(undefined, pop(?TEST_SINK_H)), + ?assertEqual(0, count(?TEST_SINK_H)) + end + }, + {"logging works", + fun() -> + ?TEST_SINK:warning("test message"), + ?assertEqual(1, count(?TEST_SINK_H)), + {Level, _Time, Message, _Metadata} = pop(?TEST_SINK_H), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual("test message", Message), + ok + end + }, + {"logging with arguments works", + fun() -> + ?TEST_SINK:warning("test message ~p", [self()]), + ?assertEqual(1, count(?TEST_SINK_H)), + {Level, _Time, Message,_Metadata} = pop(?TEST_SINK_H), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)), + ok + end + }, + {"variables inplace of literals in logging statements work", + fun() -> + ?assertEqual(0, count(?TEST_SINK_H)), + Attr = [{a, alpha}, {b, beta}], + Fmt = "format ~p", + Args = [world], + ?TEST_SINK:info(Attr, "hello"), + ?TEST_SINK:info(Attr, "hello ~p", [world]), + ?TEST_SINK:info(Fmt, [world]), + ?TEST_SINK:info("hello ~p", Args), + ?TEST_SINK:info(Attr, "hello ~p", Args), + ?TEST_SINK:info([{d, delta}, {g, gamma}], Fmt, Args), + ?assertEqual(6, count(?TEST_SINK_H)), + {_Level, _Time, Message, Metadata} = pop(?TEST_SINK_H), + ?assertMatch([{a, alpha}, {b, beta}|_], Metadata), + ?assertEqual("hello", lists:flatten(Message)), + {_Level, _Time2, Message2, _Metadata2} = pop(?TEST_SINK_H), + ?assertEqual("hello world", lists:flatten(Message2)), + {_Level, _Time3, Message3, _Metadata3} = pop(?TEST_SINK_H), + ?assertEqual("format world", lists:flatten(Message3)), + {_Level, _Time4, Message4, _Metadata4} = pop(?TEST_SINK_H), + ?assertEqual("hello world", lists:flatten(Message4)), + {_Level, _Time5, Message5, _Metadata5} = pop(?TEST_SINK_H), + ?assertEqual("hello world", lists:flatten(Message5)), + {_Level, _Time6, Message6, Metadata6} = pop(?TEST_SINK_H), + ?assertMatch([{d, delta}, {g, gamma}|_], Metadata6), + ?assertEqual("format world", lists:flatten(Message6)), + ok + end + }, + {"log messages below the threshold are ignored", + fun() -> + ?assertEqual(0, count(?TEST_SINK_H)), + ?TEST_SINK:debug("this message will be ignored"), + ?assertEqual(0, count(?TEST_SINK_H)), + ?assertEqual(0, count_ignored(?TEST_SINK_H)), + lager_config:set({?TEST_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}), + ?TEST_SINK:debug("this message should be ignored"), + ?assertEqual(0, count(?TEST_SINK_H)), + %?assertEqual(1, count_ignored(?TEST_SINK_H)), + lager:set_loglevel(?TEST_SINK_H, ?MODULE, undefined, debug), + ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({?TEST_SINK, loglevel})), + ?TEST_SINK:debug("this message should be logged"), + ?assertEqual(1, count(?TEST_SINK_H)), + ?assertEqual(1, count_ignored(?TEST_SINK_H)), + ?assertEqual(debug, lager:get_loglevel(?TEST_SINK, ?MODULE)), + ok + end + } + ] + }. + +setup_sink() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, []), + application:set_env(lager, error_logger_redirect, false), + application:set_env(lager, extra_sinks, [{?TEST_SINK_H, [{handlers, [{?MODULE, info}]}]}]), + lager:start(), + gen_event:call(lager_event, ?MODULE, flush), + gen_event:call(?TEST_SINK_H, ?MODULE, flush). + setup() -> error_logger:tty(false), application:load(lager), From 1906cb247d41cd861971a535c6cbde9993598ffd Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 13 May 2015 12:52:00 -0500 Subject: [PATCH 076/102] Export get_loglevel/2 (derp) --- src/lager.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index cfbc303..ae62763 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -29,7 +29,7 @@ md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, - get_loglevel/1, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, + get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, do_log/10, pr/2]). From b8552a8cb683be0b8561ae2dbb6fe81bb8c27e2f Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 13 May 2015 12:52:15 -0500 Subject: [PATCH 077/102] Fix and cleanup tests for multiple-sinks Previously, would fail due to lager:get_loglevel/2 not being exported. --- test/lager_test_backend.erl | 81 ++++++++++++++++++------------------- 1 file changed, 40 insertions(+), 41 deletions(-) diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 459f8ed..75d37f9 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -23,12 +23,11 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). --define(TEST_SINK, '__lager_test_sink'). --define(TEST_SINK_H, '__lager_test_sink_event'). +-define(TEST_SINK_NAME, '__lager_test_sink'). %% <-- used by parse transform +-define(TEST_SINK_EVENT, '__lager_test_sink_event'). %% <-- used by lager API calls and internals for gen_event -record(state, {level :: list(), buffer :: list(), ignored :: term()}). -compile({parse_transform, lager_transform}). -%-compile([{parse_transform, lager_transform}]). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -593,15 +592,15 @@ extra_sinks_test_() -> [ {"observe that there is nothing up my sleeve", fun() -> - ?assertEqual(undefined, pop(?TEST_SINK_H)), - ?assertEqual(0, count(?TEST_SINK_H)) + ?assertEqual(undefined, pop(?TEST_SINK_EVENT)), + ?assertEqual(0, count(?TEST_SINK_EVENT)) end }, {"logging works", fun() -> - ?TEST_SINK:warning("test message"), - ?assertEqual(1, count(?TEST_SINK_H)), - {Level, _Time, Message, _Metadata} = pop(?TEST_SINK_H), + ?TEST_SINK_NAME:warning("test message"), + ?assertEqual(1, count(?TEST_SINK_EVENT)), + {Level, _Time, Message, _Metadata} = pop(?TEST_SINK_EVENT), ?assertMatch(Level, lager_util:level_to_num(warning)), ?assertEqual("test message", Message), ok @@ -609,9 +608,9 @@ extra_sinks_test_() -> }, {"logging with arguments works", fun() -> - ?TEST_SINK:warning("test message ~p", [self()]), - ?assertEqual(1, count(?TEST_SINK_H)), - {Level, _Time, Message,_Metadata} = pop(?TEST_SINK_H), + ?TEST_SINK_NAME:warning("test message ~p", [self()]), + ?assertEqual(1, count(?TEST_SINK_EVENT)), + {Level, _Time, Message,_Metadata} = pop(?TEST_SINK_EVENT), ?assertMatch(Level, lager_util:level_to_num(warning)), ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)), ok @@ -619,29 +618,29 @@ extra_sinks_test_() -> }, {"variables inplace of literals in logging statements work", fun() -> - ?assertEqual(0, count(?TEST_SINK_H)), + ?assertEqual(0, count(?TEST_SINK_EVENT)), Attr = [{a, alpha}, {b, beta}], Fmt = "format ~p", Args = [world], - ?TEST_SINK:info(Attr, "hello"), - ?TEST_SINK:info(Attr, "hello ~p", [world]), - ?TEST_SINK:info(Fmt, [world]), - ?TEST_SINK:info("hello ~p", Args), - ?TEST_SINK:info(Attr, "hello ~p", Args), - ?TEST_SINK:info([{d, delta}, {g, gamma}], Fmt, Args), - ?assertEqual(6, count(?TEST_SINK_H)), - {_Level, _Time, Message, Metadata} = pop(?TEST_SINK_H), + ?TEST_SINK_NAME:info(Attr, "hello"), + ?TEST_SINK_NAME:info(Attr, "hello ~p", [world]), + ?TEST_SINK_NAME:info(Fmt, [world]), + ?TEST_SINK_NAME:info("hello ~p", Args), + ?TEST_SINK_NAME:info(Attr, "hello ~p", Args), + ?TEST_SINK_NAME:info([{d, delta}, {g, gamma}], Fmt, Args), + ?assertEqual(6, count(?TEST_SINK_EVENT)), + {_Level, _Time, Message, Metadata} = pop(?TEST_SINK_EVENT), ?assertMatch([{a, alpha}, {b, beta}|_], Metadata), ?assertEqual("hello", lists:flatten(Message)), - {_Level, _Time2, Message2, _Metadata2} = pop(?TEST_SINK_H), + {_Level, _Time2, Message2, _Metadata2} = pop(?TEST_SINK_EVENT), ?assertEqual("hello world", lists:flatten(Message2)), - {_Level, _Time3, Message3, _Metadata3} = pop(?TEST_SINK_H), + {_Level, _Time3, Message3, _Metadata3} = pop(?TEST_SINK_EVENT), ?assertEqual("format world", lists:flatten(Message3)), - {_Level, _Time4, Message4, _Metadata4} = pop(?TEST_SINK_H), + {_Level, _Time4, Message4, _Metadata4} = pop(?TEST_SINK_EVENT), ?assertEqual("hello world", lists:flatten(Message4)), - {_Level, _Time5, Message5, _Metadata5} = pop(?TEST_SINK_H), + {_Level, _Time5, Message5, _Metadata5} = pop(?TEST_SINK_EVENT), ?assertEqual("hello world", lists:flatten(Message5)), - {_Level, _Time6, Message6, Metadata6} = pop(?TEST_SINK_H), + {_Level, _Time6, Message6, Metadata6} = pop(?TEST_SINK_EVENT), ?assertMatch([{d, delta}, {g, gamma}|_], Metadata6), ?assertEqual("format world", lists:flatten(Message6)), ok @@ -649,20 +648,20 @@ extra_sinks_test_() -> }, {"log messages below the threshold are ignored", fun() -> - ?assertEqual(0, count(?TEST_SINK_H)), - ?TEST_SINK:debug("this message will be ignored"), - ?assertEqual(0, count(?TEST_SINK_H)), - ?assertEqual(0, count_ignored(?TEST_SINK_H)), - lager_config:set({?TEST_SINK, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}), - ?TEST_SINK:debug("this message should be ignored"), - ?assertEqual(0, count(?TEST_SINK_H)), - %?assertEqual(1, count_ignored(?TEST_SINK_H)), - lager:set_loglevel(?TEST_SINK_H, ?MODULE, undefined, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({?TEST_SINK, loglevel})), - ?TEST_SINK:debug("this message should be logged"), - ?assertEqual(1, count(?TEST_SINK_H)), - ?assertEqual(1, count_ignored(?TEST_SINK_H)), - ?assertEqual(debug, lager:get_loglevel(?TEST_SINK, ?MODULE)), + ?assertEqual(0, count(?TEST_SINK_EVENT)), + ?TEST_SINK_NAME:debug("this message will be ignored"), + ?assertEqual(0, count(?TEST_SINK_EVENT)), + ?assertEqual(0, count_ignored(?TEST_SINK_EVENT)), + lager_config:set({?TEST_SINK_EVENT, loglevel}, {element(2, lager_util:config_to_mask(debug)), []}), + ?TEST_SINK_NAME:debug("this message should be ignored"), + ?assertEqual(0, count(?TEST_SINK_EVENT)), + ?assertEqual(1, count_ignored(?TEST_SINK_EVENT)), + lager:set_loglevel(?TEST_SINK_EVENT, ?MODULE, undefined, debug), + ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({?TEST_SINK_EVENT, loglevel})), + ?TEST_SINK_NAME:debug("this message should be logged"), + ?assertEqual(1, count(?TEST_SINK_EVENT)), + ?assertEqual(1, count_ignored(?TEST_SINK_EVENT)), + ?assertEqual(debug, lager:get_loglevel(?TEST_SINK_EVENT, ?MODULE)), ok end } @@ -674,10 +673,10 @@ setup_sink() -> application:load(lager), application:set_env(lager, handlers, []), application:set_env(lager, error_logger_redirect, false), - application:set_env(lager, extra_sinks, [{?TEST_SINK_H, [{handlers, [{?MODULE, info}]}]}]), + application:set_env(lager, extra_sinks, [{?TEST_SINK_EVENT, [{handlers, [{?MODULE, info}]}]}]), lager:start(), gen_event:call(lager_event, ?MODULE, flush), - gen_event:call(?TEST_SINK_H, ?MODULE, flush). + gen_event:call(?TEST_SINK_EVENT, ?MODULE, flush). setup() -> error_logger:tty(false), From d74d877a020859916d41fe245c3ae85efd267d2e Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Thu, 14 May 2015 16:45:28 -0400 Subject: [PATCH 078/102] Improve README on sink naming, async configuration per-sink --- README.md | 60 +++++++++++++++++++++++++++++++++++++------------------ 1 file changed, 41 insertions(+), 19 deletions(-) diff --git a/README.md b/README.md index cdbc2ab..a095dea 100644 --- a/README.md +++ b/README.md @@ -16,7 +16,7 @@ Features * When no handler is consuming a log level (eg. debug) no event is sent to the log handler * Supports multiple backends, including console and file. -* Supports multiple sinks (and eventually different sync/async policies per sink) +* Supports multiple sinks * Rewrites common OTP error messages into more readable messages * Support for pretty printing records encountered at compile time * Tolerant in the face of large or many log messages, won't out of memory the node @@ -93,32 +93,52 @@ your app.config): The available configuration options for each backend are listed in their module's documentation. -Multiple sinks --------------- -Previously, lager supported a single sink `lager_event`. Lager can now support -additional sinks with their own backend configurations. Eventually, the goal is -to support different latency and sync/async message policies. (For example, if -there were an `audit` sink, we might be willing to pay the latency costs to log -all of those messages to disk and we don't want lager to drop them in an -overload scenario.) - -To use multiple sinks (beyond the built in sink of lager and lager_event), you +Sinks +----- +Lager has traditionally supported a single sink (implemented as a +`gen_event` manager) named `lager_event` to which all backends were +connected. + +Lager now supports extra sinks; each sink can have different +sync/async message thresholds and different backends. + +### Sink configuration + +To use multiple sinks (beyond the built-in sink of lager and lager_event), you need to: 1. Setup rebar.config 2. Configure the backends in app.config -### rebar.config +#### Names + +Each sink has two names: one atom to be used like a module name for +sending messages, and that atom with `_event` appended for backend +configuration. + +This reflects the legacy behavior: `lager:info` (or `critical`, or +`debug`, etc) is a way of sending a message to a sink named +`lager_event`. Now developers can invoke `audit:info` or +`myCompanyName:debug` so long as the corresponding `audit_event` or +`myCompanyName_event` sinks are configured. + +#### rebar.config -In `rebar.config` for the containing project, include this tuple in `erl_opts`: +In `rebar.config` for the project that requires lager, include a list +of sink names (without the `_event` suffix) in `erl_opts`: -`{lager_extra_sinks, [sink1, sink2, sink3]}` +`{lager_extra_sinks, [audit]}` -### Runtime requirements +#### Runtime requirements -Sinks must be configured with backends (and possibly in the future behavioral differences). +To be useful, sinks must be configured at runtime with backends. - app.config +In `app.config` for the project that requires lager, for example, +extend the lager configuration to include an `extra_sinks` tuple with +backends (aka "handlers") and optionally `async_threshold` and +`async_threshold_window` values (see **Overload Protection** +below). If async values are not configured, no overload protection +will be applied on that sink. ```erlang [{lager, [ @@ -134,14 +154,16 @@ Sinks must be configured with backends (and possibly in the future behavioral di %% Any other sinks {extra_sinks, [ - {sink1_event, + {audit_event, [{handlers, [{lager_file_backend, [{file, "sink1.log"}, {level, info} ] }] - }] + }, + {async_threshold, 500}, + {async_threshold_window, 50}] }] } ] From 513d233ea4bba43594511154b6508921111efeb9 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Thu, 14 May 2015 16:54:25 -0400 Subject: [PATCH 079/102] Drop last bits that now duplicate information from earlier --- README.md | 3 --- 1 file changed, 3 deletions(-) diff --git a/README.md b/README.md index a095dea..5d9d90b 100644 --- a/README.md +++ b/README.md @@ -171,9 +171,6 @@ will be applied on that sink. ]. ``` -In your application you can then use `sink1:info(...)` as you normally would, but the message -will be routed into the sink handler(s) instead of the default `lager_event` handler. - Custom Formatting ----------------- All loggers have a default formatting that can be overriden. A formatter is any module that From 4f94260239393eac2d2a7d3ae0e9bad183678072 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 15 May 2015 15:40:33 -0400 Subject: [PATCH 080/102] Revert decision to throw a {sink, Sink} tuple at every backend; instead, special case the throttle --- src/error_logger_lager_h.erl | 2 +- src/lager_console_backend.erl | 16 +++++++--------- src/lager_file_backend.erl | 2 -- src/lager_handler_watcher.erl | 19 +++++++++++++------ test/lager_crash_backend.erl | 2 +- test/lager_test_backend.erl | 14 ++++++-------- 6 files changed, 28 insertions(+), 27 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 6b55b79..a19e441 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -74,7 +74,7 @@ set_high_water(N) -> gen_event:call(error_logger, ?MODULE, {set_high_water, N}, infinity). -spec init(any()) -> {ok, #state{}}. -init([{sink, Sink}, HighWaterMark]) -> +init([HighWaterMark]) -> {ok, #state{hwm=HighWaterMark}}. handle_call({set_high_water, N}, State) -> diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index eb563ba..e922ec3 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -40,8 +40,6 @@ %% @private init([Level]) when is_atom(Level) -> init(Level); -init([{sink, _Sink}|T]) -> - init(T); init([Level, true]) -> % for backwards compatibility init([Level,{lager_default_formatter,[{eol, eol()}]}]); init([Level,false]) -> % for backwards compatibility @@ -188,7 +186,7 @@ console_log_test_() -> unregister(user), register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), + gen_event:add_handler(lager_event, lager_console_backend, info), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:log(info, self(), "Test message"), receive @@ -208,7 +206,7 @@ console_log_test_() -> unregister(user), register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info, true]), + gen_event:add_handler(lager_event, lager_console_backend, [info, true]), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:info("Test message"), PidStr = pid_to_list(self()), @@ -229,7 +227,7 @@ console_log_test_() -> register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), gen_event:add_handler(lager_event, lager_console_backend, - [{sink, lager_event}, info, {lager_default_formatter, [date,"#",time,"#",severity,"#",node,"#",pid,"#", + [info, {lager_default_formatter, [date,"#",time,"#",severity,"#",node,"#",pid,"#", module,"#",function,"#",file,"#",line,"#",message,"\r\n"]}]), lager_config:set({lager_event, loglevel}, {?INFO, []}), lager:info("Test message"), @@ -252,7 +250,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), + gen_event:add_handler(lager_event, lager_console_backend, info), erlang:group_leader(Pid, whereis(lager_event)), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:debug("Test message"), @@ -282,7 +280,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), + gen_event:add_handler(lager_event, lager_console_backend, info), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), erlang:group_leader(Pid, whereis(lager_event)), lager:debug("Test message"), @@ -321,7 +319,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), + gen_event:add_handler(lager_event, lager_console_backend, info), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '!=info'), erlang:group_leader(Pid, whereis(lager_event)), @@ -352,7 +350,7 @@ console_log_test_() -> Pid = spawn(F(self())), unregister(user), register(user, Pid), - gen_event:add_handler(lager_event, lager_console_backend, [{sink, lager_event}, info]), + gen_event:add_handler(lager_event, lager_console_backend, info), lager_config:set({lager_event, loglevel}, {element(2, lager_util:config_to_mask(info)), []}), lager:set_loglevel(lager_console_backend, '=debug'), erlang:group_leader(Pid, whereis(lager_event)), diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 4036381..15292d6 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -80,8 +80,6 @@ {formatter_config, term()}. -spec init([option(),...]) -> {ok, #state{}} | {error, bad_config}. -init([{sink, _Sink}|Options]) -> - init(Options); init({FileName, LogLevel}) when is_list(FileName), is_atom(LogLevel) -> %% backwards compatability hack init([{file, FileName}, {level, LogLevel}]); diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index 6e8b739..4251db5 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -47,11 +47,8 @@ start_link(Sink, Module, Config) -> start(Sink, Module, Config) -> gen_server:start(?MODULE, [Sink, Module, Config], []). -init([Sink, Module, Config]) when is_list(Config) -> - install_handler(Sink, Module, Config), - {ok, #state{sink=Sink, module=Module, config=Config}}; init([Sink, Module, Config]) -> - install_handler(Sink, Module, [Config]), + install_handler(Sink, Module, Config), {ok, #state{sink=Sink, module=Module, config=Config}}. handle_call(_Call, _From, State) -> @@ -90,9 +87,19 @@ code_change(_OldVsn, State, _Extra) -> {ok, State}. %% internal - +install_handler(Sink, lager_backend_throttle, Config) -> + %% The lager_backend_throttle needs to know to which sink it is + %% attached, hence this admittedly ugly workaround. Handlers are + %% sensitive to the structure of the configuration sent to `init', + %% sadly, so it's not trivial to add a configuration item to be + %% ignored to backends without breaking 3rd party handlers. + install_handler2(Sink, lager_backend_throttle, [{sink, Sink}|Config]); install_handler(Sink, Module, Config) -> - case gen_event:add_sup_handler(Sink, Module, [{sink, Sink}|Config]) of + install_handler2(Sink, Module, Config). + +%% private +install_handler2(Sink, Module, Config) -> + case gen_event:add_sup_handler(Sink, Module, Config) of ok -> ?INT_LOG(debug, "Lager installed handler ~p into ~p", [Module, Sink]), lager:update_loglevel_config(Sink), diff --git a/test/lager_crash_backend.erl b/test/lager_crash_backend.erl index fa137f1..b573a73 100644 --- a/test/lager_crash_backend.erl +++ b/test/lager_crash_backend.erl @@ -27,7 +27,7 @@ -include_lib("eunit/include/eunit.hrl"). -endif. -init([{sink, _Sink}, CrashBefore, CrashAfter]) -> +init([CrashBefore, CrashAfter]) -> case is_tuple(CrashBefore) andalso (timer:now_diff(CrashBefore, os:timestamp()) > 0) of true -> %?debugFmt("crashing!~n", []), diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 75d37f9..f8f0632 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -35,8 +35,6 @@ -export([pop/0, count/0, count_ignored/0, flush/0, print_state/0]). -endif. -init([{sink, _Sink}, Level]) -> - init(Level); init(Level) -> {ok, #state{level=lager_util:config_to_mask(Level), buffer=[], ignored=[]}}. @@ -150,11 +148,11 @@ lager_test_() -> ?assertEqual(0, count()) end }, - {"test sink not running", - fun() -> - ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) - end - }, + {"test sink not running", + fun() -> + ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) + end + }, {"logging works", fun() -> lager:warning("test message"), @@ -665,7 +663,7 @@ extra_sinks_test_() -> ok end } - ] + ] }. setup_sink() -> From e78cc1c40d61d2d605410760fd8baa086218f4c6 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 15 May 2015 15:54:54 -0400 Subject: [PATCH 081/102] Backwards compatibility for any code sufficiently ill-behaved to invoke 2.x do_log directly --- src/lager.erl | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index ae62763..3df78ee 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -32,7 +32,7 @@ get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, - do_log/10, pr/2]). + do_log/9, do_log/10, pr/2]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -83,9 +83,6 @@ md(_) -> erlang:error(badarg). -dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> - dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). - -spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}. %% this is the same check that the parse transform bakes into the module at compile time %% see lager_transform (lines 173-216) @@ -137,6 +134,15 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, Size) -> dispatch_log(Severity, Metadata, Format, Args, Size). +%% backwards compatible with beams compiled with lager 2.x +dispatch_log(Severity, Metadata, Format, Args, Size) -> + dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). + +%% backwards compatible with beams compiled with lager 2.x +do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, SinkPid) -> + do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, + LevelThreshold, TraceFilters, ?DEFAULT_SINK, SinkPid). + %% TODO: %% Consider making log2/4 that takes the Level, Pid and Message params of log/3 From 2368846445aa803bc8a256c72be1368a31236845 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Fri, 15 May 2015 16:21:43 -0400 Subject: [PATCH 082/102] Update tracing docs --- README.md | 28 ++++++++++++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 5d9d90b..335d9e5 100644 --- a/README.md +++ b/README.md @@ -444,8 +444,8 @@ You can also specify multiple expressions in a filter, or use the `*` atom as a wildcard to match any message that has that attribute, regardless of its value. -Tracing to an existing logfile is also supported, if you wanted to log -warnings from a particular function in a particular module to the default `error.log`: +Tracing to an existing logfile is also supported (but see **Multiple +sink support** below): ```erlang lager:trace_file("log/error.log", [{module, mymodule}, {function, myfunction}], warning) @@ -484,6 +484,30 @@ lager:trace_console([{request, '>', 117}, {request, '<', 120}]) Using `=` is equivalent to the 2-tuple form. +### Multiple sink support + +If using multiple sinks, there are limitations on tracing that you +should be aware of. + +Traces are specific to a sink, which can be specified via trace +filters: + +```erlang +lager:trace_file("log/security.log", [{sink, audit}, {function, myfunction}], warning) +``` + +If no sink is thus specified, the default lager sink will be used. + +This has two ramifications: + +* Traces cannot intercept messages sent to a different sink. +* Tracing to a file already opened via `lager:trace_file` will only be + successful if the same sink is specified. + +The former can be ameliorated by opening multiple traces; the latter +can be fixed by rearchitecting lager's file backend, but this has not +been tackled. + Setting the truncation limit at compile-time -------------------------------------------- Lager defaults to truncating messages at 4096 bytes, you can alter this by From a8e3a9610bfc3d5a87c4f1e11f6f9e4589e67bd2 Mon Sep 17 00:00:00 2001 From: Serge Aleynikov Date: Sun, 17 May 2015 07:26:44 -0400 Subject: [PATCH 083/102] Add abbreviated severity 'sev' available to formatter --- README.md | 4 ++- src/lager_default_formatter.erl | 5 +++- src/lager_util.erl | 49 ++++++++++++++++++++------------- 3 files changed, 37 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 5d234c8..c0deccb 100644 --- a/README.md +++ b/README.md @@ -108,7 +108,9 @@ for the backend: Included is lager_default_formatter. This provides a generic, default formatting for log messages using a "semi-iolist" as configuration. Any iolist allowed elements in the configuration are printed verbatim. Atoms in the configuration are treated as metadata properties and extracted from the log message. -The metadata properties date,time, message, and severity will always exist. +The metadata properties date,time, message, severity, and sev will always exist. The sev +property represents an "abbreviated" severity which `lager_default_formatter` interprets as a +capitalized single letter encoding of the severity level (e.g. `'debug'` -> `$D`). The properties pid, file, line, module, function, and node will always exist if the parser transform is used. ``` diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl index 312f6a0..5ef85f2 100644 --- a/src/lager_default_formatter.erl +++ b/src/lager_default_formatter.erl @@ -40,7 +40,7 @@ %% or refer to other properties, if desired. You can also use a {atom, semi-iolist(), semi-iolist()} formatter, which %% acts like a ternary operator's true/false branches. %% -%% The metadata properties date,time, message, and severity will always exist. +%% The metadata properties date,time, message, severity, and sev will always exist. %% The properties pid, file, line, module, and function will always exist if the parser transform is used. %% %% Example: @@ -86,6 +86,9 @@ output(time,Msg) -> T; output(severity,Msg) -> atom_to_list(lager_msg:severity(Msg)); +output(sev,Msg) -> + %% Write brief acronym for the severity level (e.g. debug -> $D) + [lager_util:level_to_chr(lager_msg:severity(Msg))]; output(Prop,Msg) when is_atom(Prop) -> Metadata = lager_msg:metadata(Msg), make_printable(get_metadata(Prop,Metadata,<<"Undefined">>)); diff --git a/src/lager_util.erl b/src/lager_util.erl index 67894ff..9d02bd5 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -18,7 +18,8 @@ -include_lib("kernel/include/file.hrl"). --export([levels/0, level_to_num/1, num_to_level/1, config_to_mask/1, config_to_levels/1, mask_to_levels/1, +-export([levels/0, level_to_num/1, level_to_chr/1, + num_to_level/1, config_to_mask/1, config_to_levels/1, mask_to_levels/1, 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, @@ -33,25 +34,35 @@ levels() -> [debug, info, notice, warning, error, critical, alert, emergency, none]. -level_to_num(debug) -> ?DEBUG; -level_to_num(info) -> ?INFO; -level_to_num(notice) -> ?NOTICE; -level_to_num(warning) -> ?WARNING; -level_to_num(error) -> ?ERROR; -level_to_num(critical) -> ?CRITICAL; -level_to_num(alert) -> ?ALERT; -level_to_num(emergency) -> ?EMERGENCY; -level_to_num(none) -> ?LOG_NONE. - -num_to_level(?DEBUG) -> debug; -num_to_level(?INFO) -> info; -num_to_level(?NOTICE) -> notice; -num_to_level(?WARNING) -> warning; -num_to_level(?ERROR) -> error; -num_to_level(?CRITICAL) -> critical; -num_to_level(?ALERT) -> alert; +level_to_num(debug) -> ?DEBUG; +level_to_num(info) -> ?INFO; +level_to_num(notice) -> ?NOTICE; +level_to_num(warning) -> ?WARNING; +level_to_num(error) -> ?ERROR; +level_to_num(critical) -> ?CRITICAL; +level_to_num(alert) -> ?ALERT; +level_to_num(emergency) -> ?EMERGENCY; +level_to_num(none) -> ?LOG_NONE. + +level_to_chr(debug) -> $D; +level_to_chr(info) -> $I; +level_to_chr(notice) -> $N; +level_to_chr(warning) -> $W; +level_to_chr(error) -> $E; +level_to_chr(critical) -> $C; +level_to_chr(alert) -> $A; +level_to_chr(emergency) -> $M; +level_to_chr(none) -> $ . + +num_to_level(?DEBUG) -> debug; +num_to_level(?INFO) -> info; +num_to_level(?NOTICE) -> notice; +num_to_level(?WARNING) -> warning; +num_to_level(?ERROR) -> error; +num_to_level(?CRITICAL) -> critical; +num_to_level(?ALERT) -> alert; num_to_level(?EMERGENCY) -> emergency; -num_to_level(?LOG_NONE) -> none. +num_to_level(?LOG_NONE) -> none. -spec config_to_mask(atom()|string()) -> {'mask', integer()}. config_to_mask(Conf) -> From 6226ef621d71332526066d6438d2a688726a0603 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Mon, 18 May 2015 22:49:58 -0500 Subject: [PATCH 084/102] Make sure we use the real line number --- src/lager_transform.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 1546c04..abeb8d7 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -178,7 +178,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {call,Line, {remote,Line,{atom,Line,lager_config},{atom,Line,get}}, [{tuple,Line,[{atom,Line,SinkName},{atom,Line,loglevel}]}, - {tuple,Line,[{integer,Line,0},{nil,1}]}]}]}, + {tuple,Line,[{integer,Line,0},{nil,Line}]}]}]}, %% {undefined, undefined, _} -> {error, lager_not_running}; [{clause,Line, [{tuple,Line, From 060402b9beb8a1960052de5d96552dcece5fc9e8 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 19 May 2015 10:21:46 -0500 Subject: [PATCH 085/102] Use macro here instead of naked atom --- src/lager_transform.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index abeb8d7..d3f9db8 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -174,7 +174,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {'case',Line, {tuple,Line, [{call,Line,{atom,Line,whereis},[{atom,Line,SinkName}]}, - {call,Line,{atom,Line,whereis},[{atom,Line,lager_event}]}, %% <--lager_event is ?DEFAULT_SINK + {call,Line,{atom,Line,whereis},[{atom,Line,?DEFAULT_SINK}]}, {call,Line, {remote,Line,{atom,Line,lager_config},{atom,Line,get}}, [{tuple,Line,[{atom,Line,SinkName},{atom,Line,loglevel}]}, From 30a5010990c12ba2dc5e6281c55f091c80764320 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 19 May 2015 10:27:05 -0500 Subject: [PATCH 086/102] Silence some compiler warnings during tests --- test/crash.erl | 4 ++-- test/pr_nested_record_test.erl | 6 ++---- 2 files changed, 4 insertions(+), 6 deletions(-) diff --git a/test/crash.erl b/test/crash.erl index aed4f1f..bb871c9 100644 --- a/test/crash.erl +++ b/test/crash.erl @@ -10,8 +10,8 @@ -export([start/0]). -record(state, { - host, - port + host :: term(), + port :: term() }). start() -> diff --git a/test/pr_nested_record_test.erl b/test/pr_nested_record_test.erl index 7a6e284..9e2fbf5 100644 --- a/test/pr_nested_record_test.erl +++ b/test/pr_nested_record_test.erl @@ -2,13 +2,11 @@ -compile([{parse_transform, lager_transform}]). --record(a, {field1, field2}). --record(b, {field1, field2}). +-record(a, {field1 :: term(), field2 :: term()}). +-record(b, {field1 :: term() , field2 :: term()}). --ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). --endif. nested_record_test() -> A = #a{field1 = x, field2 = y}, From 3223014933cfeab88599306696331dbab2cee343 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 19 May 2015 10:31:37 -0500 Subject: [PATCH 087/102] Use Meta as a better var name to capture intent --- src/lager_transform.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index d3f9db8..eda84d1 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -130,7 +130,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {atom, Line, App}]}, {nil, Line}}, DefaultAttrs0) end, - {Traces, Message, Arguments} = case Arguments0 of + {Meta, Message, Arguments} = case Arguments0 of [Format] -> {DefaultAttrs, Format, {atom, Line, none}}; [Arg1, Arg2] -> @@ -207,7 +207,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, [{atom,Line,Severity}, - Traces, + Meta, Message, Arguments, {integer, Line, get(truncation_size)}, From 5fef54c289822f8e88814fdba815847077fe22c1 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Thu, 21 May 2015 13:29:07 -0500 Subject: [PATCH 088/102] Comma derp --- rebar.config | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rebar.config b/rebar.config index 1f68404..bfcecec 100644 --- a/rebar.config +++ b/rebar.config @@ -20,7 +20,7 @@ %% ------------------------------------------------------------------- {erl_opts, [ - {lager_extra_sinks, ['__lager_test_sink']} + {lager_extra_sinks, ['__lager_test_sink']}, debug_info, report, verbose, From 31cf6c02a9cd6a4ae9680b00202d07abf81212c1 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Thu, 21 May 2015 16:26:23 -0500 Subject: [PATCH 089/102] Check configuration as suggested in gh#253 Previously bad configurations would be silently ignored. Now they will throw an error tuple. --- src/lager_app.erl | 25 ++++++++++++++++++++----- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 96db4fc..d2d5451 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -81,7 +81,9 @@ start_handlers(Sink, Handlers) -> lager_config:global_get(handlers, []) ++ lists:map(fun({Module, Config}) -> check_handler_config(Module, Config), - start_handler(Sink, Module, Config) + start_handler(Sink, Module, Config); + (_) -> + throw({error, bad_config}) end, expand_handlers(Handlers))), ok. @@ -91,7 +93,7 @@ start_handler(Sink, Module, Config) -> [Sink, Module, Config]), {Module, Watcher, Sink}. -check_handler_config({lager_file_backend, F}, _Config) -> +check_handler_config({lager_file_backend, F}, Config) when is_list(Config) -> Fs = case get(?FILENAMES) of undefined -> ordsets:new(); X -> X @@ -106,9 +108,10 @@ check_handler_config({lager_file_backend, F}, _Config) -> ordsets:add_element(F, Fs)) end, ok; - -check_handler_config(_Other, _Config) -> - ok. +check_handler_config(_Handler, Config) when is_list(Config) orelse is_atom(Config) -> + ok; +check_handler_config(Handler, _BadConfig) -> + throw({error, {bad_config, Handler}}). clean_up_config_checks() -> erase(?FILENAMES). @@ -332,12 +335,24 @@ check_handler_config_test_() -> Bad = expand_handlers([{lager_console_backend, info}, {lager_file_backend, [{file, "same_file.log"}]}, {lager_file_backend, [{file, "same_file.log"}, {level, info}]}]), + AlsoBad = [{lager_logstash_backend, + {level, info}, + {output, {udp, "localhost", 5000}}, + {format, json}, + {json_encoder, jiffy}}], + BadToo = [{fail, {fail}}], [ {"lager_file_backend_good", ?_assertEqual([ok, ok, ok], [ check_handler_config(M,C) || {M,C} <- Good ]) }, {"lager_file_backend_bad", ?_assertThrow({error, bad_config}, [ check_handler_config(M,C) || {M,C} <- Bad ]) + }, + {"Invalid config dies", + ?_assertThrow({error, bad_config}, start_handlers(foo, AlsoBad)) + }, + {"Invalid config dies", + ?_assertThrow({error, {bad_config, _}}, start_handlers(foo, BadToo)) } ]. -endif. From 9879bcc201afc26588e46b753052a28b8bf8a516 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Fri, 22 May 2015 15:32:20 -0500 Subject: [PATCH 090/102] Remove tabs that snuck in last commit --- src/error_logger_lager_h.erl | 4 +-- src/lager_file_backend.erl | 56 +++++++++++++++++------------------- 2 files changed, 29 insertions(+), 31 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index f174e5b..2bdab73 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -74,7 +74,7 @@ init([HighWaterMark, GlStrategy]) -> {ok, #state{shaper=Shaper, groupleader_strategy=GlStrategy}}. handle_call({set_high_water, N}, #state{shaper=Shaper} = State) -> - NewShaper = Shaper#lager_shaper{hwm=N}, + NewShaper = Shaper#lager_shaper{hwm=N}, {ok, ok, State#state{shaper = NewShaper}}; handle_call(_Request, State) -> {ok, unknown_call, State}. @@ -84,7 +84,7 @@ handle_event(Event, #state{shaper=Shaper} = State) -> {true, 0, NewShaper} -> eval_gl(Event, State#state{shaper=NewShaper}); {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} when Drop > 0 -> - ?LOGFMT(warning, self(), + ?LOGFMT(warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, Hwm]), eval_gl(Event, State#state{shaper=NewShaper}); diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 07cc243..fd645f0 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -63,7 +63,7 @@ size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), - shaper :: lager_shaper(), + shaper :: lager_shaper(), formatter :: atom(), formatter_config :: any(), sync_on :: {'mask', integer()}, @@ -76,7 +76,7 @@ -type option() :: {file, string()} | {level, lager:log_level()} | {size, non_neg_integer()} | {date, string()} | {count, non_neg_integer()} | {high_water_mark, non_neg_integer()} | - {sync_interval, non_neg_integer()} | + {sync_interval, non_neg_integer()} | {sync_size, non_neg_integer()} | {sync_on, lager:log_level()} | {check_interval, non_neg_integer()} | {formatter, atom()} | {formatter_config, term()}. @@ -134,43 +134,41 @@ handle_call({set_loglevel, Level}, #state{name=Ident} = State) -> handle_call(get_loglevel, #state{level=Level} = State) -> {ok, Level, State}; handle_call({set_loghwm, Hwm}, #state{shaper=Shaper, name=Name} = State) -> - case validate_logfile_proplist([{file, Name}, {high_water_mark, Hwm}]) of + case validate_logfile_proplist([{file, Name}, {high_water_mark, Hwm}]) of false -> {ok, {error, bad_log_hwm}, State}; _ -> - NewShaper = Shaper#lager_shaper{hwm=Hwm}, - ?INT_LOG(notice, "Changed loghwm of ~s to ~p", [Name, Hwm]), - {ok, {last_loghwm, Shaper#lager_shaper.hwm}, State#state{shaper=NewShaper}} - end; + NewShaper = Shaper#lager_shaper{hwm=Hwm}, + ?INT_LOG(notice, "Changed loghwm of ~s to ~p", [Name, Hwm]), + {ok, {last_loghwm, Shaper#lager_shaper.hwm}, State#state{shaper=NewShaper}} + end; handle_call(_Request, State) -> {ok, ok, State}. %% @private handle_event({log, Message}, - #state{name=Name, level=L, shaper=Shaper, - formatter=Formatter,formatter_config=FormatConfig} = State) -> + #state{name=Name, level=L, shaper=Shaper, formatter=Formatter,formatter_config=FormatConfig} = State) -> case lager_util:is_loggable(Message,L,{lager_file_backend, Name}) of true -> - case lager_util:check_hwm(Shaper) of - {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} -> - NewState = case Drop > 0 of - true -> - Report = io_lib:format("lager_file_backend dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, Hwm]), - ReportMsg = lager_msg:new(Report, warning, [], []), - write(State, - lager_msg:timestamp(ReportMsg), - lager_msg:severity_as_int(ReportMsg), - Formatter:format(ReportMsg, FormatConfig)); - false -> - State - end, - {ok,write(NewState#state{shaper=NewShaper}, - lager_msg:timestamp(Message), - lager_msg:severity_as_int(Message), - Formatter:format(Message,FormatConfig)) }; - {false, _, NewShaper} -> - {ok, State#state{shaper=NewShaper}} - end; + case lager_util:check_hwm(Shaper) of + {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} -> + NewState = case Drop > 0 of + true -> + Report = io_lib:format( + "lager_file_backend dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", + [Drop, Hwm]), + ReportMsg = lager_msg:new(Report, warning, [], []), + write(State, lager_msg:timestamp(ReportMsg), + lager_msg:severity_as_int(ReportMsg), Formatter:format(ReportMsg, FormatConfig)); + false -> + State + end, + {ok,write(NewState#state{shaper=NewShaper}, + lager_msg:timestamp(Message), lager_msg:severity_as_int(Message), + Formatter:format(Message,FormatConfig))}; + {false, _, NewShaper} -> + {ok, State#state{shaper=NewShaper}} + end; false -> {ok, State} end; From 466384b8c27ee3e0d8d691cccea4593b18bd1bc6 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Mon, 1 Jun 2015 13:35:03 -0500 Subject: [PATCH 091/102] Pin goldrush to 0.1.7 release Goldrush 0.1.7 provides for additional comparison operators in traces. --- rebar.config | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rebar.config b/rebar.config index bfcecec..10e49bc 100644 --- a/rebar.config +++ b/rebar.config @@ -44,7 +44,7 @@ nowarn_export_all ]}. {deps, [ - {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {branch, "master"}}} + {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.7"}}} ]}. {xref_checks, []}. From 9cc4abc36661afcccf91ce86de39aad30bd2fc3a Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 23 Jun 2015 16:10:03 -0400 Subject: [PATCH 092/102] Support _unsafe message levels that dodge trunc_io --- include/lager.hrl | 25 +++++++++++++++---------- src/lager_transform.erl | 19 +++++++++++++++++-- 2 files changed, 32 insertions(+), 12 deletions(-) diff --git a/include/lager.hrl b/include/lager.hrl index 124e17d..f9ddf99 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -22,6 +22,11 @@ -define(LEVELS, [debug, info, notice, warning, error, critical, alert, emergency, none]). +%% Use of these "functions" means that the argument list will not be +%% truncated for safety +-define(LEVELS_UNSAFE, + [debug_unsafe, info_unsafe, notice_unsafe, warning_unsafe, error_unsafe, critical_unsafe, alert_unsafe, emergency_unsafe]). + -define(DEBUG, 128). -define(INFO, 64). -define(NOTICE, 32). @@ -64,7 +69,7 @@ Level, [{pid,Pid},{line,?LINE},{file,?FILE},{module,?MODULE}], [])} - )). + )). %% FOR INTERNAL USE ONLY %% internal non-blocking logging call @@ -102,14 +107,14 @@ -endif. -record(lager_shaper, { - %% how many messages per second we try to deliver - hwm = undefined :: 'undefined' | pos_integer(), - %% how many messages we've received this second - mps = 0 :: non_neg_integer(), - %% the current second - lasttime = os:timestamp() :: erlang:timestamp(), - %% count of dropped messages this second - dropped = 0 :: non_neg_integer() - }). + %% how many messages per second we try to deliver + hwm = undefined :: 'undefined' | pos_integer(), + %% how many messages we've received this second + mps = 0 :: non_neg_integer(), + %% the current second + lasttime = os:timestamp() :: erlang:timestamp(), + %% count of dropped messages this second + dropped = 0 :: non_neg_integer() + }). -type lager_shaper() :: #lager_shaper{}. diff --git a/src/lager_transform.erl b/src/lager_transform.erl index eda84d1..1a1a681 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -89,7 +89,13 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), do_transform(Line, SinkName, Function, Arguments0); false -> - Stmt + case lists:member(Function, ?LEVELS_UNSAFE) of + true -> + SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), + do_transform(Line, SinkName, Function, Arguments0, unsafe); + false -> + Stmt + end end; false -> list_to_tuple(transform_statement(tuple_to_list(Stmt), Sinks)) @@ -102,6 +108,9 @@ transform_statement(Stmt, _Sinks) -> Stmt. do_transform(Line, SinkName, Severity, Arguments0) -> + do_transform(Line, SinkName, Severity, Arguments0, safe). + +do_transform(Line, SinkName, Severity, Arguments0, Safety) -> SeverityAsInt=lager_util:level_to_num(Severity), DefaultAttrs0 = {cons, Line, {tuple, Line, [ {atom, Line, module}, {atom, Line, get(module)}]}, @@ -168,6 +177,12 @@ do_transform(Line, SinkName, Severity, Arguments0) -> LevelVar = make_varname("__Level", Line), TracesVar = make_varname("__Traces", Line), PidVar = make_varname("__Pid", Line), + LogFun = case Safety of + safe -> + do_log; + unsafe -> + do_log_unsafe + end, %% Wrap the call to lager:dispatch_log/6 in case that will avoid doing any work if this message is not elegible for logging %% See lager.erl (lines 89-100) for lager:dispatch_log/6 %% case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of @@ -205,7 +220,7 @@ do_transform(Line, SinkName, Severity, Arguments0) -> [[{op, Line, 'orelse', {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], - [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, do_log}}, + [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, LogFun}}, [{atom,Line,Severity}, Meta, Message, From cf5b39c64f87a856f446fbc1d49e6362ab63ec69 Mon Sep 17 00:00:00 2001 From: "John R. Daily" Date: Tue, 23 Jun 2015 17:28:22 -0400 Subject: [PATCH 093/102] Severities must be convertible to numbers --- include/lager.hrl | 2 +- src/lager_transform.erl | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/include/lager.hrl b/include/lager.hrl index f9ddf99..82116f0 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -25,7 +25,7 @@ %% Use of these "functions" means that the argument list will not be %% truncated for safety -define(LEVELS_UNSAFE, - [debug_unsafe, info_unsafe, notice_unsafe, warning_unsafe, error_unsafe, critical_unsafe, alert_unsafe, emergency_unsafe]). + [{debug_unsafe, debug}, {info_unsafe, info}, {notice_unsafe, notice}, {warning_unsafe, warning}, {error_unsafe, error}, {critical_unsafe, critical}, {alert_unsafe, alert}, {emergency_unsafe, emergency}]). -define(DEBUG, 128). -define(INFO, 64). diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 1a1a681..ceddb22 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -89,10 +89,10 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), do_transform(Line, SinkName, Function, Arguments0); false -> - case lists:member(Function, ?LEVELS_UNSAFE) of - true -> + case lists:keyfind(Function, 1, ?LEVELS_UNSAFE) of + {Function, Severity} -> SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), - do_transform(Line, SinkName, Function, Arguments0, unsafe); + do_transform(Line, SinkName, Severity, Arguments0, unsafe); false -> Stmt end From 512fac4a210f3a2646ff340590d365a91ef48417 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 23 Jun 2015 16:40:23 -0500 Subject: [PATCH 094/102] Add unsafe_formatting option --- src/lager.erl | 37 ++++++++++++++++++++++++++++--- test/lager_test_backend.erl | 44 ++++++++++++++++++++++++++++++++----- 2 files changed, 72 insertions(+), 9 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 575e2bb..303d98e 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -31,8 +31,8 @@ name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4, - safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/6, dispatch_log/9, - do_log/9, do_log/10, pr/2, pr/3]). + safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/6, dispatch_log/9, + do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -98,6 +98,13 @@ dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity %% @private Should only be called externally from code generated from the parse transform do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> + %% XXX FIXME : DO NOT RELEASE + %% If you use the unsafe fun, make sure to underscore the _Size variable in the function head. + %FormatFun = fun() -> unsafe_format(Format, Args) end, + FormatFun = fun() -> safe_format_chop(Format, Args, Size) end, + do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). + +do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun) -> {Destinations, TraceSinkPid} = case TraceFilters of [] -> {[], undefined}; @@ -108,7 +115,7 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr true -> Msg = case Args of A when is_list(A) -> - safe_format_chop(Format,Args,Size); + FormatFun(); _ -> Format end, @@ -130,6 +137,13 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr ok end. +%% @private Should only be called externally from code generated from the parse transform +%% Specifically, it would be level ++ `_unsafe' as in `info_unsafe'. +do_log_unsafe(Severity, Metadata, Format, Args, _Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> + FormatFun = fun() -> unsafe_format(Format, Args) end, + do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). + + %% backwards compatible with beams compiled with lager 1.x dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, Size) -> dispatch_log(Severity, Metadata, Format, Args, Size). @@ -486,6 +500,23 @@ safe_format(Fmt, Args, Limit, Options) -> safe_format_chop(Fmt, Args, Limit) -> safe_format(Fmt, Args, Limit, [{chomp, true}]). +%% @private Print the format string `Fmt' with `Args' without a size limit. +%% This is unsafe because the output of this function is unbounded. +%% +%% Log messages with unbounded size will kill your application dead as +%% OTP mechanisms stuggle to cope with them. So this function is +%% intended only for messages which have a reasonable bounded +%% size before they're formatted. +%% +%% If the format string is invalid or not enough arguments are +%% supplied a 'FORMAT ERROR' message is printed instead with the +%% offending arguments. The caller is NOT crashed. +unsafe_format(Fmt, Args) -> + try io_lib:format(Fmt, Args) + catch + _:_ -> io_lib:format("FORMAT ERROR: ~p ~p", [Fmt, Args]) + end. + %% @doc Print a record lager found during parse transform pr(Record, Module) when is_tuple(Record), is_atom(element(1, Record)) -> pr(Record, Module, []); diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 93a69b1..51dd738 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -168,11 +168,11 @@ lager_test_() -> ?assertEqual(0, count()) end }, - {"test sink not running", - fun() -> - ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) - end - }, + {"test sink not running", + fun() -> + ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) + end + }, {"logging works", fun() -> lager:warning("test message"), @@ -183,6 +183,16 @@ lager_test_() -> ok end }, + {"unsafe logging works", + fun() -> + lager:warning_unsafe("test message"), + ?assertEqual(1, count()), + {Level, _Time, Message, _Metadata} = pop(), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual("test message", Message), + ok + end + }, {"logging with arguments works", fun() -> lager:warning("test message ~p", [self()]), @@ -193,6 +203,16 @@ lager_test_() -> ok end }, + {"unsafe logging with args works", + fun() -> + lager:warning("test message ~p", [self()]), + ?assertEqual(1, count()), + {Level, _Time, Message,_Metadata} = pop(), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)), + ok + end + }, {"logging works from inside a begin/end block", fun() -> ?assertEqual(0, count()), @@ -592,6 +612,13 @@ lager_test_() -> ok end }, + {"unsafe messages really are not truncated", + fun() -> + lager:info_unsafe("doom, doom has come upon you all ~p", [string:copies("doom", 1500)]), + {_, _, Msg,_Metadata} = pop(), + ?assert(length(lists:flatten(Msg)) == 6035) + end + }, {"can't store invalid metadata", fun() -> ?assertEqual(ok, lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}])), @@ -881,7 +908,6 @@ error_logger_redirect_test_() -> ?assertEqual("Привет!", lists:flatten(Msg)) end }, - {"error messages are truncated at 4096 characters", fun() -> sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), @@ -890,6 +916,7 @@ error_logger_redirect_test_() -> ?assert(length(lists:flatten(Msg)) < 5100) end }, + {"info reports are printed", fun() -> sync_error_logger:info_report([{this, is}, a, {silly, format}]), @@ -1349,6 +1376,11 @@ safe_format_test() -> ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))), ok. +unsafe_format_test() -> + ?assertEqual("foo bar", lists:flatten(lager:unsafe_format("~p ~p", [foo, bar]))), + ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:unsafe_format("~p ~p ~p", [foo, bar]))), + ok. + async_threshold_test_() -> {foreach, fun() -> From 6a458a428003af3c4575e31e93af5c8c48fa72ba Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Wed, 24 Jun 2015 14:40:12 -0500 Subject: [PATCH 095/102] Make 'dynamic' conform to OTP gh#271 --- src/lager_sup.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_sup.erl b/src/lager_sup.erl index 789fede..b52fae6 100644 --- a/src/lager_sup.erl +++ b/src/lager_sup.erl @@ -41,7 +41,7 @@ init([]) -> %% Maybe a new API to handle the sink and its policy? Children = [ {lager, {gen_event, start_link, [{local, lager_event}]}, - permanent, 5000, worker, [dynamic]}, + permanent, 5000, worker, dynamic}, {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []}, permanent, 5000, supervisor, [lager_handler_watcher_sup]}], From e0abc34a3280a0171de5e0f4c1f9e51a44ab0706 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Thu, 25 Jun 2015 16:25:48 -0500 Subject: [PATCH 096/102] Remove testing crutch --- src/lager.erl | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 303d98e..66358a2 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -98,9 +98,6 @@ dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity %% @private Should only be called externally from code generated from the parse transform do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> - %% XXX FIXME : DO NOT RELEASE - %% If you use the unsafe fun, make sure to underscore the _Size variable in the function head. - %FormatFun = fun() -> unsafe_format(Format, Args) end, FormatFun = fun() -> safe_format_chop(Format, Args, Size) end, do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). From 5bcdadeccbf46f3078dab0d53b1c59e006a73d68 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Mon, 29 Jun 2015 14:37:58 -0500 Subject: [PATCH 097/102] Add log_unsafe/4 --- src/lager.erl | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 66358a2..4c1d677 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -26,12 +26,13 @@ %% API -export([start/0, log/3, log/4, log/5, + log_unsafe/4, md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4, - safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/6, dispatch_log/9, + safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9, do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. @@ -83,16 +84,18 @@ md(_) -> erlang:error(badarg). --spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}. +-spec dispatch_log(atom(), log_level(), list(), string(), list() | none, pos_integer(), safe | unsafe) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}. %% this is the same check that the parse transform bakes into the module at compile time %% see lager_transform (lines 173-216) -dispatch_log(Sink, Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> +dispatch_log(Sink, Severity, Metadata, Format, Args, Size, Safety) when is_atom(Severity)-> SeverityAsInt=lager_util:level_to_num(Severity), case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of {undefined, undefined, _} -> {error, lager_not_running}; {undefined, _LagerEventPid0, _} -> {error, {sink_not_configured, Sink}}; - {SinkPid, _LagerEventPid1, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] -> + {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= safe andalso ( (Level band SeverityAsInt) /= 0 orelse Traces /= [] ) -> do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); + {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= unsafe andalso ( (Level band SeverityAsInt) /= 0 orelse Traces /= [] ) -> + do_log_unsafe(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); _ -> ok end. @@ -147,7 +150,7 @@ dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, %% backwards compatible with beams compiled with lager 2.x dispatch_log(Severity, Metadata, Format, Args, Size) -> - dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size). + dispatch_log(?DEFAULT_SINK, Severity, Metadata, Format, Args, Size, safe). %% backwards compatible with beams compiled with lager 2.x do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, SinkPid) -> @@ -173,12 +176,16 @@ log(Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> log(Level, Metadata, Format, Args) when is_list(Metadata) -> dispatch_log(Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION). +log_unsafe(Level, Metadata, Format, Args) when is_list(Metadata) -> + dispatch_log(?DEFAULT_SINK, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION, unsafe). + + %% @doc Manually log a message into lager without using the parse transform. -spec log(atom(), log_level(), pid() | atom() | [tuple(),...], string(), list()) -> ok | {error, lager_not_running}. log(Sink, Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> - dispatch_log(Sink, Level, [{pid,Pid}], Format, Args, ?DEFAULT_TRUNCATION); + dispatch_log(Sink, Level, [{pid,Pid}], Format, Args, ?DEFAULT_TRUNCATION, safe); log(Sink, Level, Metadata, Format, Args) when is_list(Metadata) -> - dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION). + dispatch_log(Sink, Level, Metadata, Format, Args, ?DEFAULT_TRUNCATION, safe). validate_trace_filters(Filters, Level, Backend) -> Sink = proplists:get_value(sink, Filters, ?DEFAULT_SINK), From 2e81dc3b0e25154a412e0c18d5d838239e68e645 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Mon, 13 Jul 2015 11:41:15 -0500 Subject: [PATCH 098/102] Add some warnings around _unsafe --- README.md | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/README.md b/README.md index 5e37514..535e938 100644 --- a/README.md +++ b/README.md @@ -20,6 +20,7 @@ Features * Rewrites common OTP error messages into more readable messages * Support for pretty printing records encountered at compile time * Tolerant in the face of large or many log messages, won't out of memory the node +* Optional feature to bypass log size truncation ("unsafe") * Supports internal time and date based rotation, as well as external rotation tools * Syslog style log level comparison flags * Colored terminal output (requires R16+) @@ -263,6 +264,30 @@ related processes crash, you can set a limit: It is probably best to keep this number small. +"Unsafe" +-------- +The unsafe code pathway bypasses the normal lager formatting code and uses the +same code as error_logger in OTP. This provides a marginal speedup to your logging +code (we measured between 0.5-1.3% improvement during our benchmarking; others have +reported better improvements.) + +This is a **dangerous** feature. It *will not* protect you against +large log messages - large messages can kill your application and even your +Erlang VM dead due to memory exhaustion as large terms are copied over and +over in a failure cascade. We strongly recommend that this code pathway +only be used by log messages with a well bounded upper size of around 500 bytes. + +If there's any possibility the log messages could exceed that limit, you should +use the normal lager message formatting code which will provide the appropriate +size limitations and protection against memory exhaustion. + +If you want to format an unsafe log message, you may use the severity level (as +usual) followed by `_unsafe`. Here's an example: + +```erlang +lager:info_unsafe("The quick brown ~s jumped over the lazy ~s", ["fox", "dog"]). +``` + Runtime loglevel changes ------------------------ You can change the log level of any lager backend at runtime by doing the From 7f9281169683179caf9c37801a9b40e78fe02c04 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 21 Jul 2015 09:05:42 -0500 Subject: [PATCH 099/102] Use '_lager_event' for sinks During code review we decided that using Sink ++ '_lager_event' would provide better isolation for gen_event names than Sink ++ '_event' as we had been using up to this point. For example a sink called 'audit' is now 'audit_lager_event' than 'audit_event' which might clash with a user's predefined own module or process name. --- README.md | 10 +++++----- src/lager_app.erl | 11 +++++++++-- src/lager_transform.erl | 11 +++++++++-- test/lager_test_backend.erl | 4 ++-- 4 files changed, 25 insertions(+), 11 deletions(-) diff --git a/README.md b/README.md index 535e938..645d3aa 100644 --- a/README.md +++ b/README.md @@ -114,19 +114,19 @@ need to: #### Names Each sink has two names: one atom to be used like a module name for -sending messages, and that atom with `_event` appended for backend +sending messages, and that atom with `_lager_event` appended for backend configuration. This reflects the legacy behavior: `lager:info` (or `critical`, or `debug`, etc) is a way of sending a message to a sink named `lager_event`. Now developers can invoke `audit:info` or -`myCompanyName:debug` so long as the corresponding `audit_event` or -`myCompanyName_event` sinks are configured. +`myCompanyName:debug` so long as the corresponding `audit_lager_event` or +`myCompanyName_lager_event` sinks are configured. #### rebar.config In `rebar.config` for the project that requires lager, include a list -of sink names (without the `_event` suffix) in `erl_opts`: +of sink names (without the `_lager_event` suffix) in `erl_opts`: `{lager_extra_sinks, [audit]}` @@ -155,7 +155,7 @@ will be applied on that sink. %% Any other sinks {extra_sinks, [ - {audit_event, + {audit_lager_event, [{handlers, [{lager_file_backend, [{file, "sink1.log"}, diff --git a/src/lager_app.erl b/src/lager_app.erl index d2d5451..bb05a2c 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -164,14 +164,21 @@ wrap_proplist_value(undefined) -> wrap_proplist_value(Value) -> {ok, Value}. +%% The default sink has always been lager_event. Using 'lager_lager_event' is likely to break +%% historical code and lots of tests. +make_internal_sink_name(lager) -> ?DEFAULT_SINK; + +make_internal_sink_name(Sink) -> + list_to_atom(atom_to_list(Sink) ++ "_lager_event"). + configure_sink(Sink, SinkDef) -> lager_config:new_sink(Sink), - ChildId = list_to_atom(atom_to_list(Sink) ++ "_event"), + ChildId = make_internal_sink_name(Sink), _ = supervisor:start_child(lager_sup, {ChildId, {gen_event, start_link, [{local, Sink}]}, - permanent, 5000, worker, [dynamic]}), + permanent, 5000, worker, dynamic}), determine_async_behavior(Sink, wrap_proplist_value( proplists:get_value(async_threshold, SinkDef)), diff --git a/src/lager_transform.erl b/src/lager_transform.erl index ceddb22..ee1640e 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -79,6 +79,13 @@ walk_body(Acc, []) -> walk_body(Acc, [H|T]) -> walk_body([transform_statement(H, get(sinks))|Acc], T). +%% 'lager' is special cased because its sink has *always* been named 'lager_event' +make_internal_sink_name(lager) -> ?DEFAULT_SINK; + +%% Everything else should be Sink++_lager_event +make_internal_sink_name(Sink) -> + list_to_atom(atom_to_list(Sink) ++ "_lager_event"). + transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, {atom, _Line3, Function}}, Arguments0} = Stmt, Sinks) -> @@ -86,12 +93,12 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, true -> case lists:member(Function, ?LEVELS) of true -> - SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), + SinkName = make_internal_sink_name(Module), do_transform(Line, SinkName, Function, Arguments0); false -> case lists:keyfind(Function, 1, ?LEVELS_UNSAFE) of {Function, Severity} -> - SinkName = list_to_atom(atom_to_list(Module) ++ "_event"), + SinkName = make_internal_sink_name(Module), do_transform(Line, SinkName, Severity, Arguments0, unsafe); false -> Stmt diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 51dd738..3b41ca5 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -27,8 +27,8 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). --define(TEST_SINK_NAME, '__lager_test_sink'). %% <-- used by parse transform --define(TEST_SINK_EVENT, '__lager_test_sink_event'). %% <-- used by lager API calls and internals for gen_event +-define(TEST_SINK_NAME, '__lager_test_sink'). %% <-- used by parse transform +-define(TEST_SINK_EVENT, '__lager_test_sink_lager_event'). %% <-- used by lager API calls and internals for gen_event -record(state, {level :: list(), buffer :: list(), ignored :: term()}). -compile({parse_transform, lager_transform}). From d7cd9fc36d016dd50ccbb7ddddc5b3d04bc19d21 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 21 Jul 2015 11:14:06 -0500 Subject: [PATCH 100/102] Rename list_all_sinks --- src/lager.erl | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index 4c1d677..7cb0fb2 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -29,7 +29,7 @@ log_unsafe/4, md/0, md/1, trace/2, trace/3, trace_file/2, trace_file/3, trace_file/4, trace_console/1, trace_console/2, - name_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, + list_all_sinks/0, clear_all_traces/0, stop_trace/1, stop_trace/3, status/0, get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4, safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9, @@ -295,7 +295,7 @@ stop_trace_int({Backend, _Filter, _Level} = Trace, Sink) -> end, ok. -name_all_sinks() -> +list_all_sinks() -> sets:to_list( lists:foldl(fun({_Watcher, _Handler, Sink}, Set) -> sets:add_element(Sink, Set) @@ -314,7 +314,7 @@ clear_traces_by_sink(Sinks) -> clear_all_traces() -> Handlers = lager_config:global_get(handlers, []), - clear_traces_by_sink(name_all_sinks()), + clear_traces_by_sink(list_all_sinks()), _ = lager_util:trace_filter(none), lager_config:global_set(handlers, lists:filter( @@ -338,7 +338,7 @@ find_traces(Sinks) -> status() -> Handlers = lager_config:global_get(handlers, []), - Sinks = lists:sort(name_all_sinks()), + Sinks = lists:sort(list_all_sinks()), Traces = find_traces(Sinks), TraceCount = case length(Traces) of 0 -> 1; From 25b700d930291976f9fce08cb183bfda93554124 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 21 Jul 2015 11:32:24 -0500 Subject: [PATCH 101/102] {ok, exists} is accounted for in the code path Removed comment --- src/lager.erl | 1 - 1 file changed, 1 deletion(-) diff --git a/src/lager.erl b/src/lager.erl index 7cb0fb2..db503ef 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -233,7 +233,6 @@ trace_file(File, Filter, Level, Options) -> end, case Res of {ok, _} -> - %% XXX Double-check this logic for {ok, exists} add_trace_to_loglevel_config(Trace, Sink), {ok, {{lager_file_backend, FileName}, Filter, Level}}; {error, _} = E -> From 20edd1519a8d17958a76f1a0dc5533ad9c49d443 Mon Sep 17 00:00:00 2001 From: Mark Allen Date: Tue, 21 Jul 2015 14:09:15 -0500 Subject: [PATCH 102/102] Make sink name construction common & test Based on code review comments put this function into util. Added a couple simple unit tests for sanity checking purposes. --- src/lager_app.erl | 9 +-------- src/lager_transform.erl | 11 ++--------- src/lager_util.erl | 16 +++++++++++++++- 3 files changed, 18 insertions(+), 18 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index bb05a2c..3d8791d 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -164,16 +164,9 @@ wrap_proplist_value(undefined) -> wrap_proplist_value(Value) -> {ok, Value}. -%% The default sink has always been lager_event. Using 'lager_lager_event' is likely to break -%% historical code and lots of tests. -make_internal_sink_name(lager) -> ?DEFAULT_SINK; - -make_internal_sink_name(Sink) -> - list_to_atom(atom_to_list(Sink) ++ "_lager_event"). - configure_sink(Sink, SinkDef) -> lager_config:new_sink(Sink), - ChildId = make_internal_sink_name(Sink), + ChildId = lager_util:make_internal_sink_name(Sink), _ = supervisor:start_child(lager_sup, {ChildId, {gen_event, start_link, diff --git a/src/lager_transform.erl b/src/lager_transform.erl index ee1640e..208a069 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -79,13 +79,6 @@ walk_body(Acc, []) -> walk_body(Acc, [H|T]) -> walk_body([transform_statement(H, get(sinks))|Acc], T). -%% 'lager' is special cased because its sink has *always* been named 'lager_event' -make_internal_sink_name(lager) -> ?DEFAULT_SINK; - -%% Everything else should be Sink++_lager_event -make_internal_sink_name(Sink) -> - list_to_atom(atom_to_list(Sink) ++ "_lager_event"). - transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, {atom, _Line3, Function}}, Arguments0} = Stmt, Sinks) -> @@ -93,12 +86,12 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, Module}, true -> case lists:member(Function, ?LEVELS) of true -> - SinkName = make_internal_sink_name(Module), + SinkName = lager_util:make_internal_sink_name(Module), do_transform(Line, SinkName, Function, Arguments0); false -> case lists:keyfind(Function, 1, ?LEVELS_UNSAFE) of {Function, Severity} -> - SinkName = make_internal_sink_name(Module), + SinkName = lager_util:make_internal_sink_name(Module), do_transform(Line, SinkName, Severity, Arguments0, unsafe); false -> Stmt diff --git a/src/lager_util.erl b/src/lager_util.erl index 8317bbf..76fdda6 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -23,7 +23,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, check_hwm/1, make_internal_sink_name/1]). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -524,6 +524,14 @@ discard_messages(Second, Count) -> Count end. +%% @private Build an atom for the gen_event process based on a sink name. +%% For historical reasons, the default gen_event process for lager itself is named +%% `lager_event'. For all other sinks, it is SinkName++`_lager_event' +make_internal_sink_name(lager) -> + ?DEFAULT_SINK; +make_internal_sink_name(Sink) -> + list_to_atom(atom_to_list(Sink) ++ "_lager_event"). + -ifdef(TEST). parse_test() -> @@ -781,4 +789,10 @@ expand_path_test() -> end, ok. +sink_name_test_() -> + [ + ?_assertEqual(lager_event, make_internal_sink_name(lager)), + ?_assertEqual(audit_lager_event, make_internal_sink_name(audit)) + ]. + -endif.