Merge pull request erlang-lager#556 from aeternity/uw-silence-with-tr…

…ace-3.9.2

Allow trace filter to silence log output (updated)

README.md

@@ -786,6 +786,15 @@ a black hole; nothing is passed through.  A filter of `{null, true}` means
 *everything* passes through. No other values for the null filter are valid and
 will be rejected.
 
+### Silencing filters
+A special log level, `silence` can be used together with a filter in order
+to suppress specific log output. This can be useful if a backend has been
+configured for a particular log level, but a particular set of log messages
+clutters the log. If these come from a dependency, they might be difficult
+to remove entirely, and it might not be desireable to do so in general.
+In such situations, a trace filter with log level `silence` can turn them
+off selectively, while letting other messages through as before.
+
 ### Multiple sink support
 
 If using multiple sinks, there are limitations on tracing that you

src/lager_util.erl

@@ -77,6 +77,8 @@ num_to_level(?EMERGENCY) -> emergency;
 num_to_level(?LOG_NONE)  -> none.
 
 -spec config_to_mask(atom()|string()) -> {'mask', integer()}.
+config_to_mask(silence) ->
+    silence;
 config_to_mask(Conf) ->
     Levels = config_to_levels(Conf),
     {mask, lists:foldl(fun(Level, Acc) ->
@@ -419,6 +421,8 @@ trace_acc([{Key, '<', Val}|T], Acc) ->
 
 check_traces(_, _,  [], Acc) ->
     lists:flatten(Acc);
+check_traces(Attrs, Level, [{_, silence, _} = Flow|Flows], Acc) ->
+    check_traces(Attrs, Level, Flows, [check_trace(Attrs, Flow)|Acc]);
 check_traces(Attrs, Level, [{_, {mask, FilterLevel}, _}|Flows], Acc) when (Level band FilterLevel) == 0 ->
     check_traces(Attrs, Level, Flows, Acc);
 check_traces(Attrs, Level, [{Filter, _, _}|Flows], Acc) when length(Attrs) < length(Filter) ->
@@ -429,13 +433,16 @@ check_traces(Attrs, Level, [Flow|Flows], Acc) ->
 check_trace(Attrs, {Filter, _Level, Dest}) when is_list(Filter) ->
     check_trace(Attrs, {trace_all(Filter), _Level, Dest});
 
-check_trace(Attrs, {Filter, _Level, Dest}) when is_tuple(Filter) ->
+check_trace(Attrs, {Filter, Level, Dest} = F) when is_tuple(Filter) ->
     Made = gre:make(Attrs, [list]),
     glc:handle(?DEFAULT_TRACER, Made),
     Match = glc_lib:matches(Filter, Made),
     case Match of
         true ->
-            Dest;
+            case Level of
+                silence -> {silence, Dest};
+                _        -> Dest
+            end;
         false ->
             []
     end.
@@ -445,13 +452,17 @@ is_loggable(Msg, {mask, Mask}, MyName) ->
     %% using syslog style comparison flags
     %S = lager_msg:severity_as_int(Msg),
     %?debugFmt("comparing masks ~.2B and ~.2B -> ~p~n", [S, Mask, S band Mask]),
-    (lager_msg:severity_as_int(Msg) band Mask) /= 0 orelse
-    lists:member(MyName, lager_msg:destinations(Msg));
+    (not lists:member({silence, MyName}, lager_msg:destinations(Msg)))
+        andalso
+          ((lager_msg:severity_as_int(Msg) band Mask) /= 0 orelse
+           lists:member(MyName, lager_msg:destinations(Msg)));
 is_loggable(Msg, SeverityThreshold, MyName) when is_atom(SeverityThreshold) ->
     is_loggable(Msg, level_to_num(SeverityThreshold), MyName);
 is_loggable(Msg, SeverityThreshold, MyName) when is_integer(SeverityThreshold) ->
-    lager_msg:severity_as_int(Msg) =< SeverityThreshold orelse
-    lists:member(MyName, lager_msg:destinations(Msg)).
+    (not lists:member({silence, MyName}, lager_msg:destinations(Msg)))
+        andalso
+        (lager_msg:severity_as_int(Msg) =< SeverityThreshold orelse
+         lists:member(MyName, lager_msg:destinations(Msg))).
 
 i2l(I) when I < 10  -> [$0, $0+I];
 i2l(I)              -> integer_to_list(I).

test/lager_trace_test.erl

@@ -13,6 +13,7 @@
 -define(SECOND_LOG_ENTRY_TIMEOUT, 1000). % 1 second
 
 -define(FNAME, "test/test1.log").
+-define(FNAME2, "test/test2.log").
 
 trace_test_() ->
     {timeout,
@@ -48,7 +49,8 @@ trace_test_() ->
                  application:unset_env(lager, async_threshold),
                  error_logger:tty(true)
          end,
-         [{"Trace combined with log_root",
+         [
+          {"Trace combined with log_root",
              fun() ->
                  lager:info([{tag, mytag}], "Test message"),
 
@@ -75,6 +77,77 @@ trace_test_() ->
              end}
           ]}}.
 
+trace_silence_test_() ->
+    {timeout,
+     10,
+     {foreach,
+         fun() ->
+                 file:write_file(?FNAME2, ""),
+                 error_logger:tty(false),
+                 application:load(lager),
+                 application:set_env(lager, log_root, "test"),
+                 application:set_env(lager, handlers,
+                                     [{lager_file_backend,
+                                       [{file, "test2.log"},
+                                        {level, info},
+                                        {formatter, lager_default_formatter},
+                                        {formatter_config, [message, "\n"]}
+                                       ]}]),
+                 application:set_env(lager, traces,
+                                     [{{lager_file_backend, "test2.log"},
+                                       [{tag, silencetag}], silence}]),
+                 application:set_env(lager, error_logger_redirect, false),
+                 application:set_env(lager, async_threshold, undefined),
+                 lager:start()
+         end,
+         fun(_) ->
+                 file:delete(?FNAME2),
+                 application:stop(lager),
+                 application:stop(goldrush),
+                 application:unset_env(lager, log_root),
+                 application:unset_env(lager, handlers),
+                 application:unset_env(lager, traces),
+                 application:unset_env(lager, error_logger_redirect),
+                 application:unset_env(lager, async_threshold),
+                 error_logger:tty(true)
+         end,
+         [
+          {"Trace filter silences output",
+             fun() ->
+                 %% One message is supposed to get through, the other not
+                 lager:info([{tag, mytag}], "Test message"),
+                 lager:info([{tag, silencetag}], "This shouldn't get logged"),
+
+                 % Wait until we have the expected log entry in the log file.
+                 case wait_until(fun() ->
+                                         count_lines(?FNAME2) >= 1
+                                 end, ?FIRST_LOG_ENTRY_TIMEOUT) of
+                     ok ->
+                         ok;
+                     {error, timeout} ->
+                         throw({file_empty, file:read_file(?FNAME)})
+                 end,
+
+                 % Let's wait a little to see that we don't get a duplicate log
+                 % entry.
+                 case wait_until(fun() ->
+                                         count_lines(?FNAME2) >= 2
+                                 end, ?SECOND_LOG_ENTRY_TIMEOUT) of
+                     ok ->
+                         throw({too_many_entries, file:read_file(?FNAME)});
+                     {error, timeout} ->
+                         ok
+                 end,
+                 {ok, Bin} = file:read_file(?FNAME2),
+                 case Bin of
+                     <<"Test message\n">> ->
+                         ok;
+                     _ ->
+                         throw({unexpected_output_in_log, Bin})
+                 end
+             end}
+          ]}}.
+
 % Wait until Fun() returns true.
 wait_until(Fun, Timeout) ->
     wait_until(Fun, Timeout, {8, 13}).