From 121c4c5241bf0d062f937694971cbb2ee54b4ee8 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Wed, 5 Oct 2011 23:33:05 -0400 Subject: [PATCH] Initial implementation of 'tracing' --- include/lager.hrl | 2 +- src/lager.erl | 33 ++++++++------ src/lager_app.erl | 5 ++- src/lager_transform.erl | 89 +++++++++++++++++++++++++++++++++---- src/lager_util.erl | 58 +++++++++++++++++++++++- test/lager_test_backend.erl | 45 ++++++++++++++++++- 6 files changed, 203 insertions(+), 29 deletions(-) diff --git a/include/lager.hrl b/include/lager.hrl index 56d13ad..1c42a93 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -52,7 +52,7 @@ end). -define(SHOULD_LOG(Level), - lager_util:level_to_num(Level) =< lager_mochiglobal:get(loglevel, ?LOG_NONE)). + lager_util:level_to_num(Level) =< element(1, lager_mochiglobal:get(loglevel, {?LOG_NONE, []}))). -define(NOTIFY(Level, Pid, Format, Args), gen_event:notify(lager_event, {log, lager_util:level_to_num(Level), diff --git a/src/lager.erl b/src/lager.erl index c1cd4d0..49d2bea 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -22,7 +22,7 @@ %% API -export([start/0, - log/7, log/8, log/3, log/4, + log/8, log_dest/9, log/3, log/4, get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, minimum_loglevel/1, posix_error/1, safe_format/3, safe_format_chop/3]). @@ -50,24 +50,27 @@ start_ok(App, {error, Reason}) -> erlang:error({app_start_failed, App, Reason}). %% @private --spec log(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), list()) -> +-spec log(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), string(), list()) -> ok | {error, lager_not_running}. -log(Level, Module, Function, Line, Pid, Time, Message) -> +log(Level, Module, Function, Line, Pid, Time, Format, Args) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - safe_format_chop("~s", [Message], 4096)], - safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). + safe_format_chop(Format, Args, 4096)], + safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). %% @private --spec log(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), string(), list()) -> +-spec log_dest(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), list(), string(), list()) -> ok | {error, lager_not_running}. -log(Level, Module, Function, Line, Pid, Time, Format, Args) -> +log_dest(_Level, _Module, _Function, _Line, _Pid, _Time, [], _Format, _Args) -> + ok; +log_dest(Level, Module, Function, Line, Pid, Time, Dest, Format, Args) -> Timestamp = lager_util:format_time(Time), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), safe_format_chop(Format, Args, 4096)], - safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). + safe_notify({log, Dest, lager_util:level_to_num(Level), Timestamp, Msg}). + %% @doc Manually log a message into lager without using the parse transform. -spec log(log_level(), pid(), list()) -> ok | {error, lager_not_running}. @@ -75,7 +78,7 @@ log(Level, Pid, Message) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), safe_format_chop("~s", [Message], 4096)], - safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). + safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). %% @doc Manually log a message into lager without using the parse transform. -spec log(log_level(), pid(), string(), list()) -> ok | {error, lager_not_running}. @@ -83,14 +86,15 @@ log(Level, Pid, Format, Args) -> Timestamp = lager_util:format_time(), Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), safe_format_chop(Format, Args, 4096)], - safe_notify(lager_util:level_to_num(Level), Timestamp, Msg). + safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). %% @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), %% recalculate min log level MinLog = minimum_loglevel(get_loglevels()), - lager_mochiglobal:put(loglevel, MinLog), + {_, Traces} = lager_mochiglobal:get(loglevel), + lager_mochiglobal:put(loglevel, {MinLog, Traces}), Reply. %% @doc Set the loglevel for a particular backend that has multiple identifiers @@ -99,7 +103,8 @@ set_loglevel(Handler, Ident, Level) when is_atom(Level) -> Reply = gen_event:call(lager_event, Handler, {set_loglevel, Ident, Level}, infinity), %% recalculate min log level MinLog = minimum_loglevel(get_loglevels()), - lager_mochiglobal:put(loglevel, MinLog), + {_, Traces} = lager_mochiglobal:get(loglevel), + lager_mochiglobal:put(loglevel, {MinLog, Traces}), Reply. %% @doc Get the loglevel for a particular backend. In the case that the backend @@ -132,13 +137,13 @@ minimum_loglevel([]) -> minimum_loglevel(Levels) -> erlang:hd(lists:reverse(lists:sort(Levels))). -safe_notify(Level, Timestamp, Msg) -> +safe_notify(Event) -> case whereis(lager_event) of undefined -> %% lager isn't running {error, lager_not_running}; Pid -> - gen_event:sync_notify(Pid, {log, Level, Timestamp, Msg}) + gen_event:sync_notify(Pid, Event) end. %% @doc Print the format string `Fmt' with `Args' safely with a size diff --git a/src/lager_app.erl b/src/lager_app.erl index 6fa1bec..e398501 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -32,7 +32,7 @@ start() -> start(_StartType, _StartArgs) -> %% until lager is completely started, allow all messages to go through - lager_mochiglobal:put(loglevel, ?DEBUG), + lager_mochiglobal:put(loglevel, {?DEBUG, []}), {ok, Pid} = lager_sup:start_link(), Handlers = case application:get_env(lager, handlers) of undefined -> @@ -47,7 +47,8 @@ start(_StartType, _StartArgs) -> %% mask the messages we have no use for MinLog = lager:minimum_loglevel(lager:get_loglevels()), - lager_mochiglobal:put(loglevel, MinLog), + {_, Traces} = lager_mochiglobal:get(loglevel), + lager_mochiglobal:put(loglevel, {MinLog, Traces}), SavedHandlers = case application:get_env(lager, error_logger_redirect) of {ok, false} -> diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 7c6d91c..7a0d501 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -58,16 +58,55 @@ walk_body(Acc, [H|T]) -> walk_body([transform_statement(H)|Acc], T). transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, - {atom, Line3, Severity}}, Arguments} = Stmt) -> + {atom, Line3, Severity}}, Arguments0} = Stmt) -> case lists:member(Severity, ?LEVELS) of true -> + DefaultAttrs = {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}]}, + {nil, Line}}}}, + {Traces, Arguments} = case Arguments0 of + [Format] -> + {DefaultAttrs, [Format, {nil, Line}]}; + [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 Arg1 of + {cons, _, {tuple, _, _}, _} -> + {concat_lists(Arg1, DefaultAttrs), + [Arg2, {nil,Line}]}; + _ -> + {DefaultAttrs, [Arg1, Arg2]} + end; + [Attrs, Format, Args] -> + {concat_lists(Attrs, DefaultAttrs), [Format, Args]} + end, %% a case to check the mochiglobal 'loglevel' key against the %% message we're trying to log - {'case',Line, + LevelVar = list_to_atom("Level" ++ atom_to_list(get(module)) ++ + integer_to_list(Line)), + TraceVar = list_to_atom("Traces" ++atom_to_list(get(module)) ++ + integer_to_list(Line)), + MatchVar = list_to_atom("X" ++ atom_to_list(get(module)) ++ + integer_to_list(Line)), + ResultVar = list_to_atom("Res" ++ atom_to_list(get(module)) ++ + integer_to_list(Line)), + {block, Line, [ + {match,Line, {tuple,Line,[{var,Line,LevelVar},{var,Line,TraceVar}]}, + {call,Line, {remote,Line,{atom,Line,lager_mochiglobal},{atom,Line,get}}, + [{atom,Line,loglevel}, + {tuple,Line, + [{integer,Line,?LOG_NONE}, {nil,Line}]}]}}, + {match, Line, + {var, Line, ResultVar}, + {'case',Line, {op,Line,'>=', - {call,Line, - {remote,Line,{atom,Line,lager_mochiglobal},{atom,Line,get}}, - [{atom,Line,loglevel},{integer,Line,?LOG_NONE}]}, + {var, Line, LevelVar}, {integer, Line, lager_util:level_to_num(Severity)}}, [{clause,Line, [{atom,Line,true}], %% yes, we log! @@ -88,7 +127,38 @@ transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, | Arguments ]}]}, %% No, don't log - {clause,Line3,[{var,Line3,'_'}],[],[{atom,Line3,ok}]}]}; + {clause,Line3,[{var,Line3,'_'}],[],[{atom,Line3,ok}]}]}}, + {'case', Line, {var, Line3, TraceVar}, + [{clause, Line3, [{nil, Line3}], [], [{var, Line3, ResultVar}]}, + {clause, Line3, [{var, Line3, MatchVar}], + [[{call,1,{atom,1,is_list},[{var,1,MatchVar}]}]], + [{call, Line, {remote, Line1, {atom, Line2, lager}, + {atom, Line3, log_dest}}, [ + {atom, Line3, Severity}, + {atom, Line3, get(module)}, + {atom, Line3, get(function)}, + {integer, Line3, Line}, + {call, Line3, {atom, Line3 ,self}, []}, + {call, Line3, {remote, Line3, + {atom, Line3 ,lager_util}, + {atom,Line3,maybe_utc}}, + [{call,Line3,{remote,Line3, + {atom,Line3,lager_util}, + {atom,Line3,localtime_ms}},[]}]}, + {call, Line3, {remote, Line3, + {atom, Line3, lager_util}, + {atom, Line3, check_traces}}, + [Traces, + {integer, Line3, + lager_util:level_to_num(Severity)}, + {var, Line3, TraceVar}, + {nil, Line3}]} + | Arguments + ]}]}, + {clause, Line3, [{var, Line3, '_'}], [], [{var, + Line3, ResultVar}]} + ]} + ]}; false -> Stmt end; @@ -108,5 +178,8 @@ transform_statement(Stmt) when is_list(Stmt) -> transform_statement(Stmt) -> Stmt. - - +%% concat 2 list ASTs by replacing the terminating [] in A with the contents of B +concat_lists({nil, _Line}, B) -> + B; +concat_lists({cons, Line, Element, Tail}, B) -> + {cons, Line, Element, concat_lists(Tail, B)}. diff --git a/src/lager_util.erl b/src/lager_util.erl index 60e25a0..5339636 100644 --- a/src/lager_util.erl +++ b/src/lager_util.erl @@ -21,7 +21,7 @@ -export([levels/0, level_to_num/1, num_to_level/1, open_logfile/2, ensure_logfile/4, rotate_logfile/2, format_time/0, format_time/1, localtime_ms/0, maybe_utc/1, parse_rotation_date_spec/1, - calculate_next_rotation/1]). + calculate_next_rotation/1, check_traces/4]). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -269,6 +269,35 @@ calculate_next_rotation([{date, Date}|T], {{Year, Month, Day}, _} = Now) -> NewNow = calendar:gregorian_seconds_to_datetime(Seconds), calculate_next_rotation(T, NewNow). +check_traces(_, _, [], Acc) -> + lists:flatten(Acc); +check_traces(Attrs, Level, [{_, FilterLevel, _}|Flows], Acc) when Level > FilterLevel -> + check_traces(Attrs, Level, Flows, Acc); +check_traces(Attrs, Level, [{Filter, _, _}|Flows], Acc) when length(Attrs) < length(Filter) -> + check_traces(Attrs, Level, Flows, Acc); +check_traces(Attrs, Level, [Flow|Flows], Acc) -> + check_traces(Attrs, Level, Flows, [check_trace(Attrs, Flow)|Acc]). + +check_trace(Attrs, {Filter, _Level, Dest}) -> + case check_trace_iter(Attrs, Filter) of + true -> + Dest; + false -> + [] + end. + +check_trace_iter(_, []) -> + true; +check_trace_iter(Attrs, [{Key, Match}|T]) -> + case lists:keyfind(Key, 1, Attrs) of + {Key, _} when Match == '*' -> + check_trace_iter(Attrs, T); + {Key, Match} -> + check_trace_iter(Attrs, T); + _ -> + false + end. + -ifdef(TEST). parse_test() -> @@ -369,6 +398,31 @@ rotate_file_test() -> rotate_logfile("rotation.log", 10) end || N <- lists:seq(0, 20)]. - +check_trace_test() -> + ?assertEqual([foo], check_traces([{module, ?MODULE}], 0, [{[{module, ?MODULE}], + 0, foo}, + {[{module, test}], 0, bar}], [])), + ?assertEqual([], check_traces([{module, ?MODULE}], 0, [{[{module, ?MODULE}, + {foo, bar}], 0, foo}, + {[{module, test}], 0, bar}], [])), + ?assertEqual([bar], check_traces([{module, ?MODULE}], 0, [{[{module, ?MODULE}, + {foo, bar}], 0, foo}, + {[{module, '*'}], 0, bar}], [])), + ?assertEqual([bar], check_traces([{module, ?MODULE}], 0, [{[{module, '*'}, + {foo, bar}], 0, foo}, + {[{module, '*'}], 0, bar}], [])), + ?assertEqual([bar], check_traces([{module, ?MODULE}], 0, [{[{module, '*'}, + {foo, '*'}], 0, foo}, + {[{module, '*'}], 0, bar}], [])), + ?assertEqual([bar, foo], check_traces([{module, ?MODULE}, {foo, bar}], 0, [{[{module, '*'}, + {foo, '*'}], 0, foo}, + {[{module, '*'}], 0, bar}], [])), + ?assertEqual([], check_traces([{module, ?MODULE}, {foo, bar}], 6, [{[{module, '*'}, + {foo, '*'}], 0, foo}, + {[{module, '*'}], 0, bar}], [])), + ?assertEqual([foo], check_traces([{module, ?MODULE}, {foo, bar}], 6, [{[{module, '*'}, + {foo, '*'}], 7, foo}, + {[{module, '*'}], 0, bar}], [])), + ok. -endif. diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 85a6ee2..1371555 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -54,6 +54,8 @@ handle_call({set_loglevel, Level}, State) -> handle_call(_Request, State) -> {ok, ok, State}. +handle_event({log, [?MODULE], Level, Time, Message}, #state{buffer=Buffer} = State) -> + {ok, State#state{buffer=Buffer ++ [{Level, Time, Message}]}}; handle_event({log, Level, Time, Message}, #state{level=LogLevel, buffer=Buffer} = State) when Level =< LogLevel -> {ok, State#state{buffer=Buffer ++ [{Level, Time, Message}]}}; @@ -164,7 +166,7 @@ lager_test_() -> lager:debug("this message will be ignored"), ?assertEqual(0, count()), ?assertEqual(0, count_ignored()), - lager_mochiglobal:put(loglevel, ?DEBUG), + lager_mochiglobal:put(loglevel, {?DEBUG, []}), lager:debug("this message should be ignored"), ?assertEqual(0, count()), ?assertEqual(1, count_ignored()), @@ -175,6 +177,45 @@ lager_test_() -> ?assertEqual(debug, lager:get_loglevel(?MODULE)), ok end + }, + {"tracing works", + fun() -> + lager_mochiglobal:put(loglevel, {?ERROR, []}), + ok = lager:info("hello world"), + ?assertEqual(0, count()), + lager_mochiglobal:put(loglevel, {?ERROR, [{[{module, + ?MODULE}], ?DEBUG, ?MODULE}]}), + ok = lager:info("hello world"), + ?assertEqual(1, count()), + ok + end + }, + {"tracing works with custom attributes", + fun() -> + lager_mochiglobal:put(loglevel, {?ERROR, []}), + lager:info([{requestid, 6}], "hello world"), + ?assertEqual(0, count()), + lager_mochiglobal:put(loglevel, {?ERROR, + [{[{requestid, 6}], ?DEBUG, ?MODULE}]}), + lager:info([{requestid, 6}, {foo, bar}], "hello world"), + ?assertEqual(1, count()), + lager_mochiglobal:put(loglevel, {?ERROR, + [{[{requestid, '*'}], ?DEBUG, ?MODULE}]}), + lager:info([{requestid, 6}], "hello world"), + ?assertEqual(2, count()), + ok + end + }, + {"tracing honors loglevel", + fun() -> + lager_mochiglobal:put(loglevel, {?ERROR, [{[{module, + ?MODULE}], ?NOTICE, ?MODULE}]}), + ok = lager:info("hello world"), + ?assertEqual(0, count()), + ok = lager:notice("hello world"), + ?assertEqual(1, count()), + ok + end } ] }. @@ -649,7 +690,7 @@ error_logger_redirect_test_() -> ?assertEqual(1, count()), ?assertEqual(0, count_ignored()), lager:set_loglevel(?MODULE, error), - lager_mochiglobal:put(loglevel, ?DEBUG), + lager_mochiglobal:put(loglevel, {?DEBUG, []}), sync_error_logger:info_report([hello, world]), _ = gen_event:which_handlers(error_logger), ?assertEqual(1, count()),