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

@@ -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

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}} , []}

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.

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
+      }
+    ]
+  }.