Allow functions to be resolve on emit or on log

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

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

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