From 058181ef3ade4caa931e2f8ce90f5c777a335ba9 Mon Sep 17 00:00:00 2001 From: walrusVision Date: Thu, 2 Mar 2017 08:28:44 +1300 Subject: [PATCH] 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()->