Merge pull request #392 from walrusVision/transform_functions

Support for dynamic metadata

README.md

@@ -722,6 +722,138 @@ 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 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, 
+              [
+                 %% Placeholder              Resolve type  Callback tuple
+                {metadata_placeholder,       on_emit,      {module_name, function_name}},
+                {other_metadata_placeholder, on_log,       {module_name, function_name}}
+              ]}]}.
+```
+
+The first atom is the placeholder atom used for the substitution in your custom
+ formatter. See [Custom Formatting](#custom-formatting) for more information.
+
+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`:
+  * 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`:
+  * 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 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.
+```
+
+**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. 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

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.

src/lager_transform.erl

@@ -32,9 +32,11 @@ parse_transform(AST, Options) ->
     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, 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)),
@@ -54,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, lists:keysort(1, FromModule))),
+    walk_ast([H|Acc], T);
 walk_ast(Acc, [{function, Line, Name, Arity, Clauses}|T]) ->
     put(function, Name),
     walk_ast([{function, Line, Name, Arity,
@@ -110,6 +117,25 @@ 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, 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).
+
+
 do_transform(Line, SinkName, Severity, Arguments0) ->
     do_transform(Line, SinkName, Severity, Arguments0, safe).
 
@@ -132,15 +158,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.

test/lager_test_function_transform.erl

@@ -0,0 +1,197 @@
+%% -------------------------------------------------------------------
+%%
+%% 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_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}).
+
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-export([
+  transform_static/0,
+  transform_dynamic/0
+]).
+-endif.
+
+-ifdef(TEST).
+
+transform_static() ->
+  static_result.
+
+transform_dynamic() ->
+  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")).
+
+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
+      },
+      {"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_emit, Metadata),
+          ?assertEqual(transform_static(), Function()),
+          ok
+        end
+      },
+      {"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_emit, Metadata),
+          ?assert(Function() < Function()),
+          ?assert(Function() < Function()),
+          ?assert(Function() < Function()),
+          ?assert(Function() < Function()),
+          ok
+        end
+      },
+      {"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_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()->
+            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
+      }
+    ]
+  }.
+
+-endif.