From 4a24f8d2283d53c7c68578a29887161d3a017ed0 Mon Sep 17 00:00:00 2001 From: walrusVision Date: Fri, 17 Feb 2017 14:31:29 +1300 Subject: [PATCH 1/9] Preliminary support for funs in parse_transform This allow functions to return a value to used in the metadata for tracing or formatting. --- src/lager_transform.erl | 21 +++++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index e1f5bf9..d2b138c 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -29,12 +29,15 @@ %% @private parse_transform(AST, Options) -> + io:format("~p~n", [?MODULE]), 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, []), + Functions = proplists:get_value(lager_function_transforms, Options, []), put(print_records_flag, Enable), put(truncation_size, TruncSize), put(sinks, Sinks), + put(functions, Functions), 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)), @@ -110,6 +113,18 @@ transform_statement(Stmt, Sinks) when is_list(Stmt) -> transform_statement(Stmt, _Sinks) -> Stmt. + +add_function_transforms(_Line, DefaultAttrs, []) -> + DefaultAttrs; +add_function_transforms(Line, DefaultAttrs, [{Atom, {Module, Function}}|Remainder]) -> + io:format("Adding ~p:~p to line ~p~n", [Module, Function, Line]), + NewFunction = {tuple, Line, [ + {atom, Line, Atom}, + {call, Line, {remote, Line, {atom, Line, Module}, {atom, Line, Function}} , []} + ]}, + add_function_transforms(Line, {cons, Line, NewFunction, DefaultAttrs}, Remainder). + + do_transform(Line, SinkName, Severity, Arguments0) -> do_transform(Line, SinkName, Severity, Arguments0, safe). @@ -132,15 +147,17 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> %% 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}}}}}}}, + Functions = get(functions), + DefaultAttrs1 = add_function_transforms(Line, DefaultAttrs0, Functions), DefaultAttrs = case erlang:get(application) of undefined -> - DefaultAttrs0; + DefaultAttrs1; App -> %% stick the application in the attribute list concat_lists({cons, Line, {tuple, Line, [ {atom, Line, application}, {atom, Line, App}]}, - {nil, Line}}, DefaultAttrs0) + {nil, Line}}, DefaultAttrs1) end, {Meta, Message, Arguments} = handle_args(DefaultAttrs, Line, Arguments0), %% Generate some unique variable names so we don't accidentally export from case clauses. From c8f12eb8bc83cf10455146985c284d5a06d7cedd Mon Sep 17 00:00:00 2001 From: walrusVision Date: Mon, 27 Feb 2017 11:25:17 +1300 Subject: [PATCH 2/9] Full support for function transforms * Updated README with instructions on how to use * Basic set of tests for working and non working examples --- README.md | 24 ++++ src/lager_transform.erl | 7 +- test/lager_test_function_transform.erl | 142 +++++++++++++++++++ test/lager_test_function_transform_error.erl | 80 +++++++++++ 4 files changed, 251 insertions(+), 2 deletions(-) create mode 100644 test/lager_test_function_transform.erl create mode 100644 test/lager_test_function_transform_error.erl diff --git a/README.md b/README.md index b7508a5..1146f4b 100644 --- a/README.md +++ b/README.md @@ -636,6 +636,30 @@ and caveats noted above apply. up to and including 3.1.0 or previous. The 2-tuple form wasn't added until 3.2.0. +Setting dynamic metadata at compile-time +---------------------------------------- +Lager supports supplying metadata from external sources. You can add these by +using the `{lager_parse_transform_functions, X}` option. In rebar, you can +add it to `erl_opts`: + +```erlang +{erl_opts, [{parse_transform, lager_transform}, + {lager_function_transforms, + [{metadata_name, {module_name, function_name}]}. +``` + +The MF called should take no arguments and should return a value that can be be + formatted into a log message. + +This metadata is also persistent across processes. + +**IMPORTANT**: Since you can calling functions, be aware that using these +could have an impact on your logging performance depending on what the call +will need to do. + +Also there is no protection against against an undefined module:function or +ensuring any required apps are started. + Setting the truncation limit at compile-time -------------------------------------------- Lager defaults to truncating messages at 4096 bytes, you can alter this by diff --git a/src/lager_transform.erl b/src/lager_transform.erl index d2b138c..44bec58 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -29,7 +29,6 @@ %% @private parse_transform(AST, Options) -> - io:format("~p~n", [?MODULE]), 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, []), @@ -57,6 +56,11 @@ walk_ast(Acc, [{attribute, _, module, {Module, _PmodArgs}}=H|T]) -> walk_ast(Acc, [{attribute, _, module, Module}=H|T]) -> put(module, Module), walk_ast([H|Acc], T); +walk_ast(Acc, [{attribute, _, lager_function_transforms, FromModule }=H|T]) -> + %% Merge transform options from the module over the compile options + FromOptions = get(functions), + put(functions, orddict:merge(fun(_Key, _V1, V2) -> V2 end, FromOptions, FromModule)), + walk_ast([H|Acc], T); walk_ast(Acc, [{function, Line, Name, Arity, Clauses}|T]) -> put(function, Name), walk_ast([{function, Line, Name, Arity, @@ -117,7 +121,6 @@ transform_statement(Stmt, _Sinks) -> add_function_transforms(_Line, DefaultAttrs, []) -> DefaultAttrs; add_function_transforms(Line, DefaultAttrs, [{Atom, {Module, Function}}|Remainder]) -> - io:format("Adding ~p:~p to line ~p~n", [Module, Function, Line]), NewFunction = {tuple, Line, [ {atom, Line, Atom}, {call, Line, {remote, Line, {atom, Line, Module}, {atom, Line, Function}} , []} diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl new file mode 100644 index 0000000..2daea75 --- /dev/null +++ b/test/lager_test_function_transform.erl @@ -0,0 +1,142 @@ +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2011-2017 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. +%% +%% ------------------------------------------------------------------- + +-module(lager_test_function_transform). + +-include("lager.hrl"). + +-lager_function_transforms([ + {returns_static, {lager_test_function_transform, transform_static}}, + {returns_dynamic, {lager_test_function_transform, transform_dynamic}} +]). + +-compile({parse_transform, lager_transform}). + +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-export([ + transform_static/0, + transform_dynamic/0 +]). +-endif. + +-ifdef(TEST). + +transform_static() -> + static_result. + +transform_dynamic() -> + rand:uniform(10). + +not_running_test() -> + ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). + +setup() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, [{lager_test_backend, info}]), + application:set_env(lager, error_logger_redirect, false), + application:unset_env(lager, traces), + lager:start(), + %% There is a race condition between the application start up, lager logging its own + %% start up condition and several tests that count messages or parse the output of + %% tests. When the lager start up message wins the race, it causes these tests + %% which parse output or count message arrivals to fail. + %% + %% We introduce a sleep here to allow `flush' to arrive *after* the start up + %% message has been received and processed. + %% + %% This race condition was first exposed during the work on + %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager + %% manager killer PR. + timer:sleep(5), + gen_event:call(lager_event, lager_test_backend, flush). + + +cleanup(_) -> + catch ets:delete(lager_config), %% kill the ets config table with fire + application:stop(lager), + application:stop(goldrush), + error_logger:tty(true). + +transform_function_test_() -> + {foreach, + fun setup/0, + fun cleanup/1, + [ + {"observe that there is nothing up my sleeve", + fun() -> + ?assertEqual(undefined, lager_test_backend:pop()), + ?assertEqual(0, lager_test_backend:count()) + end + }, + {"logging works", + fun() -> + lager:warning("test message"), + ?assertEqual(1, lager_test_backend:count()), + {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), + ?assertMatch(Level, lager_util:level_to_num(warning)), + ?assertEqual("test message", Message), + ok + end + }, + {"Test calling a function returns the same content", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + ?assertEqual(transform_static(), proplists:get_value(returns_static, Metadata)), + ok + end + }, + {"Test calling a function which returns content which can change", + fun() -> + lager:warning("dynamic message 1"), + lager:warning("dynamic message 2"), + lager:warning("dynamic message 3"), + lager:warning("dynamic message 4"), + lager:warning("dynamic message 5"), + lager:warning("dynamic message 6"), + ?assertEqual(6, lager_test_backend:count()), + {_Level1, _Time1, _Message1, Metadata1} = lager_test_backend:pop(), + Replacement1 = proplists:get_value(returns_dynamic, Metadata1), + ?assert((1 =< Replacement1) and (Replacement1 =< 10)), + {_Level2, _Time2, _Message2, Metadata2} = lager_test_backend:pop(), + Replacement2 = proplists:get_value(returns_dynamic, Metadata2), + ?assert((1 =< Replacement2) and (Replacement2 =< 10)), + {_Level3, _Time3, _Message3, Metadata3} = lager_test_backend:pop(), + Replacement3 = proplists:get_value(returns_dynamic, Metadata3), + ?assert((1 =< Replacement3) and (Replacement3 =< 10)), + {_Level4, _Time4, _Message4, Metadata4} = lager_test_backend:pop(), + Replacement4 = proplists:get_value(returns_dynamic, Metadata4), + ?assert((1 =< Replacement4) and (Replacement4 =< 10)), + {_Level5, _Time5, _Message5, Metadata5} = lager_test_backend:pop(), + Replacement5 = proplists:get_value(returns_dynamic, Metadata5), + ?assert((1 =< Replacement5) and (Replacement5 =< 10)), + {_Level6, _Time6, _Message6, Metadata6} = lager_test_backend:pop(), + Replacement6 = proplists:get_value(returns_dynamic, Metadata6), + ?assert((1 =< Replacement6) and (Replacement6 =< 10)), + ok + end + } + ] + }. + +-endif. diff --git a/test/lager_test_function_transform_error.erl b/test/lager_test_function_transform_error.erl new file mode 100644 index 0000000..6cd7a53 --- /dev/null +++ b/test/lager_test_function_transform_error.erl @@ -0,0 +1,80 @@ +%% ------------------------------------------------------------------- +%% +%% Copyright (c) 2011-2017 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. +%% +%% ------------------------------------------------------------------- + +-module(lager_test_function_transform_error). + +-compile([ + {parse_transform, lager_transform} +]). + +-lager_function_transforms([ + {returns_undefined, {not_real_module_fake, fake_not_real_function}} +]). + +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. + +setup() -> + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, [{lager_test_backend, info}]), + application:set_env(lager, error_logger_redirect, false), + application:unset_env(lager, traces), + lager:start(), + %% There is a race condition between the application start up, lager logging its own + %% start up condition and several tests that count messages or parse the output of + %% tests. When the lager start up message wins the race, it causes these tests + %% which parse output or count message arrivals to fail. + %% + %% We introduce a sleep here to allow `flush' to arrive *after* the start up + %% message has been received and processed. + %% + %% This race condition was first exposed during the work on + %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager + %% manager killer PR. + timer:sleep(5), + gen_event:call(lager_event, lager_test_backend, flush). + +cleanup(_) -> + catch ets:delete(lager_config), %% kill the ets config table with fire + application:stop(lager), + application:stop(goldrush), + error_logger:tty(true). + +transform_function_error_test_() -> + {foreach, + fun setup/0, + fun cleanup/1, + [ + {"observe that there is nothing up my sleeve", + fun() -> + ?assertEqual(undefined, lager_test_backend:pop()), + ?assertEqual(0, lager_test_backend:count()) + end + }, + {"Testing a function transform for a undefined function errors", + fun() -> + ?assertError(undef, lager:warning("undefined message")), + ok + end + } + ] + }. \ No newline at end of file From 39a6055d9e75a43c6741b80f8fd3a0ed8725179a Mon Sep 17 00:00:00 2001 From: Michael Kokich Date: Mon, 27 Feb 2017 11:41:45 +1300 Subject: [PATCH 3/9] Ensure transform options are sorted before merge --- 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 44bec58..60c38ef 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -36,7 +36,7 @@ parse_transform(AST, Options) -> put(print_records_flag, Enable), put(truncation_size, TruncSize), put(sinks, Sinks), - put(functions, Functions), + put(functions, lists:keysort(1, Functions)), 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)), @@ -59,7 +59,7 @@ walk_ast(Acc, [{attribute, _, module, Module}=H|T]) -> walk_ast(Acc, [{attribute, _, lager_function_transforms, FromModule }=H|T]) -> %% Merge transform options from the module over the compile options FromOptions = get(functions), - put(functions, orddict:merge(fun(_Key, _V1, V2) -> V2 end, FromOptions, FromModule)), + put(functions, orddict:merge(fun(_Key, _V1, V2) -> V2 end, FromOptions, lists:keysort(1, FromModule))), walk_ast([H|Acc], T); walk_ast(Acc, [{function, Line, Name, Arity, Clauses}|T]) -> put(function, Name), From 777fd65df90c0d6406b1675a680c7fbce0da0eec Mon Sep 17 00:00:00 2001 From: walrusVision Date: Mon, 27 Feb 2017 17:06:43 +1300 Subject: [PATCH 4/9] Only evaluate functions on message emit. * A side effect is you can set per processes functions via lager:md/1 --- README.md | 7 ++- src/lager_default_formatter.erl | 11 +++++ src/lager_transform.erl | 4 +- test/lager_test_function_transform.erl | 66 +++++++++++++++----------- 4 files changed, 55 insertions(+), 33 deletions(-) diff --git a/README.md b/README.md index 1146f4b..a48fc79 100644 --- a/README.md +++ b/README.md @@ -649,16 +649,15 @@ add it to `erl_opts`: ``` The MF called should take no arguments and should return a value that can be be - formatted into a log message. + formatted into a log message. Any function which is not defined, loaded, or + throws an exception will return `undefined` or the provided default value. -This metadata is also persistent across processes. +This metadata is also persistent across processes. **IMPORTANT**: Since you can calling functions, be aware that using these could have an impact on your logging performance depending on what the call will need to do. -Also there is no protection against against an undefined module:function or -ensuring any required apps are started. Setting the truncation limit at compile-time -------------------------------------------- diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl index 96c8f6c..379ccd3 100644 --- a/src/lager_default_formatter.erl +++ b/src/lager_default_formatter.erl @@ -185,6 +185,15 @@ make_printable(A,{Align,W}) when is_integer(W) -> make_printable(A,_W) -> make_printable(A). +run_function(Function, Default) -> + try Function() of + Result -> + Result + catch + _:_ -> + Default + end. + get_metadata(Key, Metadata) -> get_metadata(Key, Metadata, undefined). @@ -192,6 +201,8 @@ get_metadata(Key, Metadata, Default) -> case lists:keyfind(Key, 1, Metadata) of false -> Default; + {Key, Value} when is_function(Value) -> + run_function(Value, Default); {Key, Value} -> Value end. diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 60c38ef..2a2133e 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -123,7 +123,9 @@ add_function_transforms(_Line, DefaultAttrs, []) -> add_function_transforms(Line, DefaultAttrs, [{Atom, {Module, Function}}|Remainder]) -> NewFunction = {tuple, Line, [ {atom, Line, Atom}, - {call, Line, {remote, Line, {atom, Line, Module}, {atom, Line, Function}} , []} + {'fun', Line, { + function, {atom, Line, Module}, {atom, Line, Function}, {integer, Line, 0} + }} ]}, add_function_transforms(Line, {cons, Line, NewFunction, DefaultAttrs}, Remainder). diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index 2daea75..b294f03 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -24,7 +24,8 @@ -lager_function_transforms([ {returns_static, {lager_test_function_transform, transform_static}}, - {returns_dynamic, {lager_test_function_transform, transform_dynamic}} + {returns_dynamic, {lager_test_function_transform, transform_dynamic}}, + {returns_undefined, {not_real_module_fake, fake_not_real_function}} ]). -compile({parse_transform, lager_transform}). @@ -43,7 +44,7 @@ transform_static() -> static_result. transform_dynamic() -> - rand:uniform(10). + erlang:monotonic_time(). not_running_test() -> ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). @@ -102,37 +103,46 @@ transform_function_test_() -> lager:warning("static message"), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - ?assertEqual(transform_static(), proplists:get_value(returns_static, Metadata)), + Function = proplists:get_value(returns_static, Metadata), + ?assertEqual(transform_static(), Function()), ok end }, {"Test calling a function which returns content which can change", fun() -> - lager:warning("dynamic message 1"), - lager:warning("dynamic message 2"), - lager:warning("dynamic message 3"), - lager:warning("dynamic message 4"), - lager:warning("dynamic message 5"), - lager:warning("dynamic message 6"), - ?assertEqual(6, lager_test_backend:count()), - {_Level1, _Time1, _Message1, Metadata1} = lager_test_backend:pop(), - Replacement1 = proplists:get_value(returns_dynamic, Metadata1), - ?assert((1 =< Replacement1) and (Replacement1 =< 10)), - {_Level2, _Time2, _Message2, Metadata2} = lager_test_backend:pop(), - Replacement2 = proplists:get_value(returns_dynamic, Metadata2), - ?assert((1 =< Replacement2) and (Replacement2 =< 10)), - {_Level3, _Time3, _Message3, Metadata3} = lager_test_backend:pop(), - Replacement3 = proplists:get_value(returns_dynamic, Metadata3), - ?assert((1 =< Replacement3) and (Replacement3 =< 10)), - {_Level4, _Time4, _Message4, Metadata4} = lager_test_backend:pop(), - Replacement4 = proplists:get_value(returns_dynamic, Metadata4), - ?assert((1 =< Replacement4) and (Replacement4 =< 10)), - {_Level5, _Time5, _Message5, Metadata5} = lager_test_backend:pop(), - Replacement5 = proplists:get_value(returns_dynamic, Metadata5), - ?assert((1 =< Replacement5) and (Replacement5 =< 10)), - {_Level6, _Time6, _Message6, Metadata6} = lager_test_backend:pop(), - Replacement6 = proplists:get_value(returns_dynamic, Metadata6), - ?assert((1 =< Replacement6) and (Replacement6 =< 10)), + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_dynamic, Metadata), + ?assert(Function() < Function()), + ?assert(Function() < Function()), + ?assert(Function() < Function()), + ?assert(Function() < Function()), + ok + end + }, + {"Testing a undefined function returns undefined", + fun() -> + lager:warning("Undefined error"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(returns_undefined, Metadata), + [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), + ?assertNot(erlang:function_exported(Module, Name, 0)), + ok + end + }, + {"Testing a function provided via metadata", + fun()-> + Provided = fun()-> + provided_metadata + end, + lager:md([{provided, Provided}]), + lager:warning("Provided metadata"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Function = proplists:get_value(provided, Metadata), + ?assertEqual(Provided(), Function()), ok end } From 157001081871820dffd5f994ec09c15687fe4877 Mon Sep 17 00:00:00 2001 From: Michael Kokich Date: Mon, 27 Feb 2017 17:12:29 +1300 Subject: [PATCH 5/9] Remove unnecessary test --- test/lager_test_function_transform_error.erl | 80 -------------------- 1 file changed, 80 deletions(-) delete mode 100644 test/lager_test_function_transform_error.erl diff --git a/test/lager_test_function_transform_error.erl b/test/lager_test_function_transform_error.erl deleted file mode 100644 index 6cd7a53..0000000 --- a/test/lager_test_function_transform_error.erl +++ /dev/null @@ -1,80 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% Copyright (c) 2011-2017 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. -%% -%% ------------------------------------------------------------------- - --module(lager_test_function_transform_error). - --compile([ - {parse_transform, lager_transform} -]). - --lager_function_transforms([ - {returns_undefined, {not_real_module_fake, fake_not_real_function}} -]). - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - -setup() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, error_logger_redirect, false), - application:unset_env(lager, traces), - lager:start(), - %% There is a race condition between the application start up, lager logging its own - %% start up condition and several tests that count messages or parse the output of - %% tests. When the lager start up message wins the race, it causes these tests - %% which parse output or count message arrivals to fail. - %% - %% We introduce a sleep here to allow `flush' to arrive *after* the start up - %% message has been received and processed. - %% - %% This race condition was first exposed during the work on - %% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager - %% manager killer PR. - timer:sleep(5), - gen_event:call(lager_event, lager_test_backend, flush). - -cleanup(_) -> - catch ets:delete(lager_config), %% kill the ets config table with fire - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true). - -transform_function_error_test_() -> - {foreach, - fun setup/0, - fun cleanup/1, - [ - {"observe that there is nothing up my sleeve", - fun() -> - ?assertEqual(undefined, lager_test_backend:pop()), - ?assertEqual(0, lager_test_backend:count()) - end - }, - {"Testing a function transform for a undefined function errors", - fun() -> - ?assertError(undef, lager:warning("undefined message")), - ok - end - } - ] - }. \ No newline at end of file From be3907d2ed1c30cc282fe7acd0556df424044815 Mon Sep 17 00:00:00 2001 From: walrusVision Date: Tue, 28 Feb 2017 10:23:12 +1300 Subject: [PATCH 6/9] Updated README. Fixed tests for older OTP versions --- README.md | 7 ++++--- test/lager_test_function_transform.erl | 7 ++++++- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index a48fc79..a03e48d 100644 --- a/README.md +++ b/README.md @@ -654,9 +654,10 @@ The MF called should take no arguments and should return a value that can be be This metadata is also persistent across processes. -**IMPORTANT**: Since you can calling functions, be aware that using these -could have an impact on your logging performance depending on what the call -will need to do. +**IMPORTANT**: Since this feature relies on function calls injected at the +point where a log message is emitted, your logging performance (ops/sec) +will be impacted by what the functions you call do and how much latency they +may introduce. Setting the truncation limit at compile-time diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index b294f03..82e3f01 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -44,7 +44,12 @@ transform_static() -> static_result. transform_dynamic() -> - erlang:monotonic_time(). + case lager_util:otp_version() >= 18 of + true -> + erlang:monotonic_time() + false -> + erlang:now() + end. not_running_test() -> ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). From 2d370918eb2a904a6cfb73ad4ceb4086bc2c7932 Mon Sep 17 00:00:00 2001 From: walrusVision Date: Tue, 28 Feb 2017 10:26:58 +1300 Subject: [PATCH 7/9] Fixed syntax error --- test/lager_test_function_transform.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index 82e3f01..18242a8 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -46,7 +46,7 @@ transform_static() -> transform_dynamic() -> case lager_util:otp_version() >= 18 of true -> - erlang:monotonic_time() + erlang:monotonic_time(); false -> erlang:now() end. From 058181ef3ade4caa931e2f8ce90f5c777a335ba9 Mon Sep 17 00:00:00 2001 From: walrusVision Date: Thu, 2 Mar 2017 08:28:44 +1300 Subject: [PATCH 8/9] Allow functions to be resolve on emit or on log --- README.md | 34 ++++++++++++--- src/lager_transform.erl | 8 +++- test/lager_test_function_transform.erl | 58 ++++++++++++++++++++++---- 3 files changed, 85 insertions(+), 15 deletions(-) diff --git a/README.md b/README.md index a03e48d..83d4884 100644 --- a/README.md +++ b/README.md @@ -645,19 +645,43 @@ add it to `erl_opts`: ```erlang {erl_opts, [{parse_transform, lager_transform}, {lager_function_transforms, - [{metadata_name, {module_name, function_name}]}. + [ + {metadata_placeholder, on_emit, {module_name, function_name}}, + {other_metadata_placeholder, on_log, {module_name, function_name}} + ]}]}. ``` The MF called should take no arguments and should return a value that can be be - formatted into a log message. Any function which is not defined, loaded, or - throws an exception will return `undefined` or the provided default value. + formatted into a log message. + +Following the placeholder atom you have to specify either `on_emit` or +`on_log`. This is tell the function to resolve at the time of emit or + the time of logging. + + `on_emit`: + * Functions are not resolve until the message is emitted. + * If the function cannot be resolve, not loaded or produces errors then + `undefined` or the provided default value will be returned. + * If the function call is dependent on another process, there is the chance + that message will be emitted after the dependent process has died. + + `on_log`: + * Functions are resolved regardless whether the message is emitted or not + * If the function cannot be resolved or not loaded the errors are not handled. + * Any potential errors should be handled by the calling function. If the + function returns `undefined` then it should return the provided default + value if supplied. + * Because the function is resolved at log time there should be less change + of the dependent process dying before you can resolve it, especially if + you are logging from the app which contains the module:function. This metadata is also persistent across processes. -**IMPORTANT**: Since this feature relies on function calls injected at the +**IMPORTANT**: Since `on_emit` relies on function calls injected at the point where a log message is emitted, your logging performance (ops/sec) will be impacted by what the functions you call do and how much latency they -may introduce. +may introduce. This impact will even greater with `on_log` since the calls +are injected at the point a message is logged. Setting the truncation limit at compile-time diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 2a2133e..5c2134c 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -120,13 +120,19 @@ transform_statement(Stmt, _Sinks) -> add_function_transforms(_Line, DefaultAttrs, []) -> DefaultAttrs; -add_function_transforms(Line, DefaultAttrs, [{Atom, {Module, Function}}|Remainder]) -> +add_function_transforms(Line, DefaultAttrs, [{Atom, on_emit, {Module, Function}}|Remainder]) -> NewFunction = {tuple, Line, [ {atom, Line, Atom}, {'fun', Line, { function, {atom, Line, Module}, {atom, Line, Function}, {integer, Line, 0} }} ]}, + add_function_transforms(Line, {cons, Line, NewFunction, DefaultAttrs}, Remainder); +add_function_transforms(Line, DefaultAttrs, [{Atom, on_log, {Module, Function}}|Remainder]) -> + NewFunction = {tuple, Line, [ + {atom, Line, Atom}, + {call, Line, {remote, Line, {atom, Line, Module}, {atom, Line, Function}}, []} + ]}, add_function_transforms(Line, {cons, Line, NewFunction, DefaultAttrs}, Remainder). diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl index 18242a8..1bae30b 100644 --- a/test/lager_test_function_transform.erl +++ b/test/lager_test_function_transform.erl @@ -23,9 +23,12 @@ -include("lager.hrl"). -lager_function_transforms([ - {returns_static, {lager_test_function_transform, transform_static}}, - {returns_dynamic, {lager_test_function_transform, transform_dynamic}}, - {returns_undefined, {not_real_module_fake, fake_not_real_function}} + {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, + {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, + {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, + + {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, + {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} ]). -compile({parse_transform, lager_transform}). @@ -103,22 +106,22 @@ transform_function_test_() -> ok end }, - {"Test calling a function returns the same content", + {"Testing calling a function returns the same content on emit", fun() -> lager:warning("static message"), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_static, Metadata), + Function = proplists:get_value(returns_static_emit, Metadata), ?assertEqual(transform_static(), Function()), ok end }, - {"Test calling a function which returns content which can change", + {"Testing calling a function which returns content which can change on emit", fun() -> lager:warning("dynamic message"), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_dynamic, Metadata), + Function = proplists:get_value(returns_dynamic_emit, Metadata), ?assert(Function() < Function()), ?assert(Function() < Function()), ?assert(Function() < Function()), @@ -126,17 +129,54 @@ transform_function_test_() -> ok end }, - {"Testing a undefined function returns undefined", + {"Testing a undefined function returns undefined on emit", fun() -> lager:warning("Undefined error"), ?assertEqual(1, lager_test_backend:count()), {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_undefined, Metadata), + Function = proplists:get_value(returns_undefined_emit, Metadata), [{module, Module}, {name, Name}|_] = erlang:fun_info(Function), ?assertNot(erlang:function_exported(Module, Name, 0)), ok end }, + {"Testing calling a function returns the same content on log", + fun() -> + lager:warning("static message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), + ok + end + }, + {"Testing calling a dynamic function on log which returns the same value", + fun() -> + lager:warning("dynamic message"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + ?assert(Value < transform_dynamic()), + ?assert(Value < transform_dynamic()), + ?assert(Value < transform_dynamic()), + ?assert(Value < transform_dynamic()), + ?assert(Value < transform_dynamic()), + ok + end + }, + {"Testing differences in results for on_log vs on emit from dynamic function", + fun() -> + lager:warning("on_log vs on emit"), + ?assertEqual(1, lager_test_backend:count()), + {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), + Value = proplists:get_value(returns_dynamic_log, Metadata), + Function = proplists:get_value(returns_dynamic_emit, Metadata), + FunctionResult = Function(), + ?assert(Value < FunctionResult), + ?assert(Value < Function()), + ?assert(FunctionResult < Function()), + ok + end + }, {"Testing a function provided via metadata", fun()-> Provided = fun()-> From 55f2f63575ac8463a4a4e607105085e774ef1a65 Mon Sep 17 00:00:00 2001 From: Michael Kokich Date: Wed, 31 May 2017 10:44:58 +1200 Subject: [PATCH 9/9] Update to README --- README.md | 136 +++++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 110 insertions(+), 26 deletions(-) diff --git a/README.md b/README.md index 83d4884..25835e5 100644 --- a/README.md +++ b/README.md @@ -638,45 +638,128 @@ up to and including 3.1.0 or previous. The 2-tuple form wasn't added until Setting dynamic metadata at compile-time ---------------------------------------- -Lager supports supplying metadata from external sources. You can add these by -using the `{lager_parse_transform_functions, X}` option. In rebar, you can -add it to `erl_opts`: +Lager supports supplying metadata from external sources by registering a +callback function. This metadata is also persistent across processes even if +the process dies. + +In general use you won't need to use this feature. However it is useful in +situations such as: + * Tracing information provided by + [seq_trace](http://erlang.org/doc/man/seq_trace.html) + * Contextual information about your application + * Persistent information which isn't provided by the default placeholders + * Situations where you would have to set the metadata before every logging call + +You can add the callbacks by using the `{lager_parse_transform_functions, X}` +option. It is only available when using `parse_transform`. In rebar, you can +add it to `erl_opts` as below: ```erlang {erl_opts, [{parse_transform, lager_transform}, {lager_function_transforms, [ - {metadata_placeholder, on_emit, {module_name, function_name}}, - {other_metadata_placeholder, on_log, {module_name, function_name}} + %% Placeholder Resolve type Callback tuple + {metadata_placeholder, on_emit, {module_name, function_name}}, + {other_metadata_placeholder, on_log, {module_name, function_name}} ]}]}. ``` -The MF called should take no arguments and should return a value that can be be - formatted into a log message. +The first atom is the placeholder atom used for the substitution in your custom + formatter. See [Custom Formatting](#custom-formatting) for more information. -Following the placeholder atom you have to specify either `on_emit` or -`on_log`. This is tell the function to resolve at the time of emit or - the time of logging. +The second atom is the resolve type. This specify the callback to resolve at +the time of the message being emitted or at the time of the logging call. You +have to specify either the atom `on_emit` or `on_log`. There is not a 'right' +resolve type to use, so please read the uses/caveats of each and pick the option +which fits your requirements best. - `on_emit`: - * Functions are not resolve until the message is emitted. - * If the function cannot be resolve, not loaded or produces errors then - `undefined` or the provided default value will be returned. - * If the function call is dependent on another process, there is the chance - that message will be emitted after the dependent process has died. +`on_emit`: + * The callback functions are not resolved until the message is emitted by the + backend. + * If the callback function cannot be resolved, not loaded or produces + unhandled errors then `undefined` will be returned. + * Since the callback function is dependent on a process, there is the + chance that message will be emitted after the dependent process has died + resulting in `undefined` being returned. This process can also be your own + process - `on_log`: - * Functions are resolved regardless whether the message is emitted or not - * If the function cannot be resolved or not loaded the errors are not handled. - * Any potential errors should be handled by the calling function. If the - function returns `undefined` then it should return the provided default - value if supplied. - * Because the function is resolved at log time there should be less change +`on_log`: + * The callback functions are resolved regardless whether the message is + emitted or not + * If the callback function cannot be resolved or not loaded the errors are + not handled by lager itself. + * Any potential errors in callback should be handled in the callback function + itself. + * Because the function is resolved at log time there should be less chance of the dependent process dying before you can resolve it, especially if - you are logging from the app which contains the module:function. + you are logging from the app which contains the callback. + +The third element is the callback to your function consisting of a tuple in the +form `{Module Function}`. The callback should look like the following +regardless if using `on_emit` or `on_log`: + * It should be exported + * It should takes no arguments e.g. has an arity of 0 + * It should return any traditional iolist elements or the atom `undefined` + * For errors generated within your callback see the resolve type documentation + above. + +If the callback returns `undefined` then it will follow the same fallback and +conditional operator rules as documented in the +[Custom Formatting](#custom-formatting) section. + +This example would work with `on_emit` but could be unsafe to use with +`on_log`. If the call failed in `on_emit` it would default to `undefined`, +however with `on_log` it would error. + +```erlang +-export([my_callback/0]). + +my_callback() -> + my_app_serv:call('some options'). +``` + +This example would be to safe to work with both `on_emit` and `on_log` + +```erlang +-export([my_callback/0]). + +my_callback() -> + try my_app_serv:call('some options') of + Result -> + Result + catch + _ -> + %% You could define any traditional iolist elements you wanted here + undefined + end. +``` + +Note that the callback can be any Module:Function/0. It does not have be part +of your application. For example you could use `cpu_sup:avg1/0` as your +callback function like so `{cpu_avg1, on_emit, {cpu_sup, avg1}}` + + +Examples: + +```erlang +-export([reductions/0]). + +reductions() -> + proplists:get_value(reductions, erlang:process_info(self())). +``` + +```erlang +-export([seq_trace/0]). + +seq_trace() -> + case seq_trace:get_token(label) of + {label, TraceLabel} -> + TraceLabel; + _ -> + undefined + end. +``` -This metadata is also persistent across processes. - **IMPORTANT**: Since `on_emit` relies on function calls injected at the point where a log message is emitted, your logging performance (ops/sec) will be impacted by what the functions you call do and how much latency they @@ -684,6 +767,7 @@ may introduce. This impact will even greater with `on_log` since the calls are injected at the point a message is logged. + Setting the truncation limit at compile-time -------------------------------------------- Lager defaults to truncating messages at 4096 bytes, you can alter this by