Skip to content

Loading…

Tracing without using parse transform. #105

Merged
merged 4 commits into from

3 participants

@lastres

Hi,

I'm trying to use the tracing provided by Lager without using the parse transform. I'm not sure about how to do that (if it's possible), and I might be doing something wrong. I do the following:

lager:trace_file("log/test.log", [{test, "Test"}]).

and then I log using:

lager:log(info, [{test, "Test"}], "This is a message", []).

But the logs get written to all the files, not only to log/test.log. Also, if I just log using

lager:log(info, self(), "This is a message", []).

also the message gets written to all the files (including log/test.log).

Am I doing something wrong?

I also found that the function lager:status() fails sometimes.

Erlang R15B01 (erts-5.9.1) [source] [smp:4:4] [async-threads:0] [hipe] [kernel-poll:false]

Eshell V5.9.1  (abort with ^G)
1> lager:start().
10:10:10.003 [info] Application lager started on node nonode@nohost
ok
2> lager:status().
Lager status:
File log/console.log at level info
File log/error.log at level error
Console at level info
Active Traces:
ok
3> lager:trace_file("logs/example.com.error", [{vhost, "example.com"}], error).
{ok,{[{vhost,"example.com"}],
     {mask,15},
     {lager_file_backend,"logs/example.com.error"}}}
4> lager:status().
** exception error: no function clause matching lager_util:num_to_level({mask,15}) (src/lager_util.erl, line 45)
     in function  lager:'-status/0-lc$^1/1-1-'/1 (src/lager.erl, line 209)
     in call from lager:status/0 (src/lager.erl, line 207)

I don't whether this is an error or my mistake.

Thanks for your help!

@Vagabond

Ok, so tracing is purely additive, it doesn't prevent messages going elsewhere. If you were logging in your example above at the 'debug' level, but wanted to log ALL messages referencing 'test' to a particular logfile, you'd use tracing. If the messages would normally go to other files/console/whatever, they will still do it.

Your second point is a bug. I will work up a fix.

@lastres

Ok, thank you for your fast answer. I understand that the tracing works in an additive way. However, in the example that I wrote when I do the second call:

lager:log(info, self(), "This is a message", []).

That message is written also in "log/test.log". Is that the expected behaviour?

thanks for fixing the bug!

@Vagabond

Oh, that might be a bug as well. I'll have to look into it too.

@Vagabond

Can you try that branch?

@lastres

Thank for the fix. I have looked into it and seems that the logs generated with

lager:log(info, self(), "This is a message", []).

keep on going to all files, including "log/test.log". The lager:status() function is not giving errors anymore.

@Vagabond

You're right. My test must be flawed somehow.

@Vagabond

Ok, I think I have a fix for this, but it needs #106 to be merged first.

@Vagabond

In the interests of expediency, I've merged the changes from #106 into here.

@ates

I've tried to use the adt-fix-tracing branch, but got the errors below after changed the loglevel to none:

1>lager:status().
Lager status:
File log/debug.log at level debug
Active Traces:
ok

2>lager:set_loglevel(lager_file_backend, "log/debug.log", none).
ok

3>lager:status().
** exception error: bad argument
     in function  hd/1
        called as hd([])
     in call from lager:get_loglevel/1 (src/lager.erl, line 246)
     in call from lager:'-status/0-lc$^0/1-0-'/1 (src/lager.erl, line 199)
     in call from lager:status/0 (src/lager.erl, line 198)
@lastres

Hi,

I'm also getting the same error:

1> lager:status().
Lager status:
File log/console.log at level info
File log/error.log at level error
Console at level info
Active Traces:
ok
2> lager:trace_file("log/test.log", [{test, "Test"}]).
{ok,{[{test,"Test"}],
     {mask,255},
     {lager_file_backend,"log/test.log"}}}
3> lager:status().
** exception error: bad argument
     in function  hd/1
        called as hd([])
     in call from lager:get_loglevel/1 (src/lager.erl, line 246)
     in call from lager:'-status/0-lc$^0/1-0-'/1 (src/lager.erl, line 199)
     in call from lager:status/0 (src/lager.erl, line 198)
@Vagabond

Clearly this isn't my week. Try the latest commit, please.

@ates

No exceptions now, looks like it's works. Thank you.

@lastres

It works now, thanks! :)

@Vagabond Vagabond merged commit e749242 into master

1 check passed

Details default The Travis build passed
@Vagabond Vagabond deleted the adt-fix-tracing branch
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Showing with 55 additions and 28 deletions.
  1. +39 −27 src/lager.erl
  2. +2 −0 src/lager_file_backend.erl
  3. +11 −1 src/lager_util.erl
  4. +3 −0 test/lager_test_backend.erl
View
66 src/lager.erl
@@ -61,7 +61,7 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
Pid ->
{LevelThreshold,TraceFilters} = lager_config:get(loglevel,{?LOG_NONE,[]}),
SeverityAsInt=lager_util:level_to_num(Severity),
- case (LevelThreshold band SeverityAsInt) /= 0 of
+ case (LevelThreshold band SeverityAsInt) /= 0 orelse TraceFilters /= [] of
true ->
Destinations = case TraceFilters of
[] ->
@@ -69,15 +69,20 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
_ ->
lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[])
end,
- Timestamp = lager_util:format_time(),
- Msg = case Args of
- A when is_list(A) ->
- safe_format_chop(Format,Args,Size);
- _ ->
- Format
- end,
- gen_event:sync_notify(Pid, {log, lager_msg:new(Msg, Timestamp,
- Severity, Metadata, Destinations)});
+ case (LevelThreshold band SeverityAsInt) /= 0 orelse Destinations /= [] of
+ true ->
+ Timestamp = lager_util:format_time(),
+ Msg = case Args of
+ A when is_list(A) ->
+ safe_format_chop(Format,Args,Size);
+ _ ->
+ Format
+ end,
+ gen_event:sync_notify(Pid, {log, lager_msg:new(Msg, Timestamp,
+ Severity, Metadata, Destinations)});
+ false ->
+ ok
+ end;
_ ->
ok
end
@@ -110,7 +115,7 @@ trace_file(File, Filter, Level) ->
false ->
%% install the handler
supervisor:start_child(lager_handler_watcher_sup,
- [lager_event, {lager_file_backend, File}, {File, Level}]);
+ [lager_event, {lager_file_backend, File}, {File, none}]);
_ ->
{ok, exists}
end,
@@ -120,8 +125,7 @@ trace_file(File, Filter, Level) ->
{MinLevel, Traces} = lager_config:get(loglevel),
case lists:member(Trace, Traces) of
false ->
- {_, {mask, TraceMask}, _} = Trace,
- lager_config:set(loglevel, {MinLevel bor TraceMask, [Trace|Traces]});
+ lager_config:set(loglevel, {MinLevel, [Trace|Traces]});
_ ->
ok
end,
@@ -149,8 +153,7 @@ trace(Backend, Filter, Level) ->
{MinLevel, Traces} = lager_config:get(loglevel),
case lists:member(Trace, Traces) of
false ->
- {_, {mask, TraceMask}, _} = Trace,
- lager_config:set(loglevel, {MinLevel bor TraceMask, [Trace|Traces]});
+ lager_config:set(loglevel, {MinLevel, [Trace|Traces]});
_ -> ok
end,
{ok, Trace};
@@ -159,10 +162,10 @@ trace(Backend, Filter, Level) ->
end.
stop_trace({_Filter, _Level, Target} = Trace) ->
- {_, Traces} = lager_config:get(loglevel),
+ {Level, Traces} = lager_config:get(loglevel),
NewTraces = lists:delete(Trace, Traces),
- MinLevel = minimum_loglevel(get_loglevels() ++ get_trace_levels(NewTraces)),
- lager_config:set(loglevel, {MinLevel, NewTraces}),
+ %MinLevel = minimum_loglevel(get_loglevels() ++ get_trace_levels(NewTraces)),
+ lager_config:set(loglevel, {Level, NewTraces}),
case get_loglevel(Target) of
none ->
%% check no other traces point here
@@ -178,8 +181,8 @@ stop_trace({_Filter, _Level, Target} = Trace) ->
ok.
clear_all_traces() ->
- MinLevel = minimum_loglevel(get_loglevels()),
- lager_config:set(loglevel, {MinLevel, []}),
+ {Level, _Traces} = lager_config:get(loglevel),
+ lager_config:set(loglevel, {Level, []}),
lists:foreach(fun(Handler) ->
case get_loglevel(Handler) of
none ->
@@ -205,8 +208,17 @@ status() ->
end || Handler <- Handlers],
"Active Traces:\n",
[begin
+ LevelName = case Level of
+ {mask, Mask} ->
+ case lager_util:mask_to_levels(Mask) of
+ [] -> none;
+ Levels -> hd(Levels)
+ end;
+ Num ->
+ lager_util:num_to_level(Num)
+ end,
io_lib:format("Tracing messages matching ~p at level ~p to ~p\n",
- [Filter, lager_util:num_to_level(Level), Destination])
+ [Filter, LevelName, Destination])
end || {Filter, Level, Destination} <- element(2, lager_config:get(loglevel))]],
io:put_chars(Status).
@@ -215,7 +227,7 @@ set_loglevel(Handler, Level) when is_atom(Level) ->
Reply = gen_event:call(lager_event, Handler, {set_loglevel, Level}, infinity),
%% recalculate min log level
{_, Traces} = lager_config:get(loglevel),
- MinLog = minimum_loglevel(get_loglevels() ++ get_trace_levels(Traces)),
+ MinLog = minimum_loglevel(get_loglevels()),
lager_config:set(loglevel, {MinLog, Traces}),
Reply.
@@ -225,7 +237,7 @@ set_loglevel(Handler, Ident, Level) when is_atom(Level) ->
Reply = gen_event:call(lager_event, {Handler, Ident}, {set_loglevel, Level}, infinity),
%% recalculate min log level
{_, Traces} = lager_config:get(loglevel),
- MinLog = minimum_loglevel(get_loglevels() ++ get_trace_levels(Traces)),
+ MinLog = minimum_loglevel(get_loglevels()),
lager_config:set(loglevel, {MinLog, Traces}),
Reply.
@@ -234,7 +246,10 @@ set_loglevel(Handler, Ident, Level) when is_atom(Level) ->
get_loglevel(Handler) ->
case gen_event:call(lager_event, Handler, get_loglevel, infinity) of
{mask, Mask} ->
- erlang:hd(lager_util:mask_to_levels(Mask));
+ case lager_util:mask_to_levels(Mask) of
+ [] -> none;
+ Levels -> hd(Levels)
+ end;
X when is_integer(X) ->
lager_util:num_to_level(X);
Y -> Y
@@ -266,9 +281,6 @@ minimum_loglevel(Levels) ->
Acc
end, 0, Levels).
-get_trace_levels(Traces) ->
- lists:map(fun({_, Level, _}) -> Level end, Traces).
-
%% @doc Print the format string `Fmt' with `Args' safely with a size
%% limit of `Limit'. If the format string is invalid, or not enough
%% arguments are supplied 'FORMAT ERROR' is printed with the offending
View
2 src/lager_file_backend.erl
@@ -412,6 +412,8 @@ filesystem_test_() ->
file:delete("foo.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("foo.log"),
?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}]))
end
View
12 src/lager_util.erl
@@ -30,7 +30,7 @@
-include("lager.hrl").
levels() ->
- [debug, info, notice, warning, error, critical, alert, emergency].
+ [debug, info, notice, warning, error, critical, alert, emergency, none].
level_to_num(debug) -> ?DEBUG;
level_to_num(info) -> ?INFO;
@@ -595,6 +595,8 @@ format_time_test_() ->
].
config_to_levels_test() ->
+ ?assertEqual([none], config_to_levels('none')),
+ ?assertEqual({mask, 0}, config_to_mask('none')),
?assertEqual([debug], config_to_levels('=debug')),
?assertEqual([debug], config_to_levels('<info')),
?assertEqual(levels() -- [debug], config_to_levels('!=debug')),
@@ -614,7 +616,15 @@ config_to_levels_test() ->
?assertEqual(levels() -- [debug], config_to_levels('!!!=debug')),
ok.
+config_to_mask_test() ->
+ ?assertEqual({mask, 0}, config_to_mask('none')),
+ ?assertEqual({mask, ?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY}, config_to_mask('debug')),
+ ?assertEqual({mask, ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY}, config_to_mask('warning')),
+ ?assertEqual({mask, ?DEBUG bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY}, config_to_mask('!=info')),
+ ok.
+
mask_to_levels_test() ->
+ ?assertEqual([], mask_to_levels(0)),
?assertEqual([debug], mask_to_levels(2#10000000)),
?assertEqual([debug, info], mask_to_levels(2#11000000)),
?assertEqual([debug, info, emergency], mask_to_levels(2#11000001)),
View
3 test/lager_test_backend.erl
@@ -204,7 +204,10 @@ lager_test_() ->
ok = lager:info("hello world"),
?assertEqual(0, count()),
lager:trace(?MODULE, [{module, ?MODULE}], debug),
+ %% elegible for tracing
ok = lager:info("hello world"),
+ %% NOT elegible for tracing
+ ok = lager:log(info, [{pid, self()}], "hello world"),
?assertEqual(1, count()),
ok
end
Something went wrong with that request. Please try again.