Initial implementation of 'tracing'

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),

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

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} ->

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)}.

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.

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()),