Enable lager to use the OTP logger's event pipeline

README.md

@@ -1138,6 +1138,69 @@ Example Usage:
 :lager.warning('Some message with a term: ~p', [term])
 ```
 
+Integration with OTP's Logger
+-----------------------------
+
+Now that OTP includes a modern log event pipeline, the Lager project has decided
+to work on winding down Lager development in favor of unifying the Erlang
+ecosystem behind Logger. To that end, Lager now supports being configured to use
+its parse transform to rewrite lager calls into logger calls. To enable this
+mode, the following changes are required:
+
+In sys.config:
+```
+[
+ {kernel,
+  [{logger,
+    [{handler, default, logger_std_h,
+      #{formatter => {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1}}}},
+    ]}]},
+...
+{lager, [
+        {lager_use_logger, true},
+       ...
+]}
+]
+```
+
+The logger stanza changes are not needed if you wish to use logger's default
+formatter.
+
+In your applications top level rebar.config (probably requires rebar3):
+
+```
+{overrides, [{add, [{erl_opts, [{lager_use_logger, true}]}]}]}.
+```
+
+This will force the parse transform configuration to apply to all the
+dependencies as well. Make sure you've defined the lager version in your
+toplevel application's rebar.config and that the version is high enough to
+support these options. A toplevel dependency will override any lager
+dependencies in any of your application's dependencies and thus ensure the parse
+transform is the right version.
+
+To generate a logger configuration from your lager configuration you can do:
+
+```
+lager:generate_logger_configuration()
+```
+
+If you wish to simply use your existing lager configuration as is, and have
+lager configure logger you can, in your sys.config in the lager stanza:
+
+```
+{lager, [
+        {configure_logger, true},
+       ...
+]}
+```
+
+Alternatively you can use:
+
+```
+lager:configure_logger()
+```
+
 3.x Changelog
 -------------
 3.6.8 - 21 December 2018

src/lager.erl

@@ -36,7 +36,8 @@
         get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1,
         update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4,
         safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9,
-        do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2]).
+        do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2,
+        generate_logger_config/0, configure_logger/0]).
 
 -type log_level() :: none | debug | info | notice | warning | error | critical | alert | emergency.
 -type log_level_number() :: 0..7.
@@ -689,6 +690,65 @@ rotate_handler(Handler) ->
 rotate_handler(Handler, Sink) ->
     gen_event:call(Sink, Handler, rotate, ?ROTATE_TIMEOUT).
 
+generate_logger_config() ->
+    Handlers = application:get_env(lager, handlers, lager_app:default_handlers()),
+    {Level, NewHandlers} = generate_logger_handlers(Handlers, {notice, []}),
+    {kernel, [{logger_level, Level}, {logger, NewHandlers}]}.
+
+configure_logger() ->
+    Handlers = application:get_env(lager, handlers, lager_app:default_handlers()),
+    WhitelistedLoggerHandlers = application:get_env(lager, whitelisted_logger_handlers, []),
+    [ ok = logger:remove_handler(Id) || #{id := Id} <- logger:get_handler_config(), not lists:member(Id, WhitelistedLoggerHandlers) ],
+    {Level, NewHandlers} = generate_logger_handlers(Handlers, {notice, []}),
+    logger:set_primary_config(maps:merge(logger:get_primary_config(), #{level => Level})),
+    [ ok = logger:add_handler(HandlerId, HandlerModule, HandlerConfig) || {handler, HandlerId, HandlerModule, HandlerConfig} <- NewHandlers ],
+    ok.
+
+generate_logger_handlers([], Acc) ->
+    Acc;
+generate_logger_handlers([{lager_console_backend, Config}|Tail], {CurrentLevel, Acc}) ->
+    Level = proplists:get_value(level, Config, info),
+    Formatter = proplists:get_value(formatter, Config, lager_default_formatter),
+    FormatterConfig = proplists:get_value(formatter_config, Config, []),
+    Handler = {handler, console, logger_std_h, #{level => Level, formatter =>
+                                                 {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1,
+                                                                            formatter => Formatter,
+                                                                            formatter_config => FormatterConfig}}}},
+    NewLevel = case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of
+                   true ->
+                       Level;
+                   false ->
+                       CurrentLevel
+               end,
+    generate_logger_handlers(Tail, {NewLevel, [Handler|Acc]});
+generate_logger_handlers([{lager_file_backend, Config}|Tail], {CurrentLevel, Acc}) ->
+    Level = proplists:get_value(level, Config, info),
+    File = proplists:get_value(file, Config),
+    LogRoot = application:get_env(lager, log_root, ""),
+    Size = proplists:get_value(size, Config, 10485760),
+    Count = proplists:get_value(count, Config, 5),
+    Formatter = proplists:get_value(formatter, Config, lager_default_formatter),
+    FormatterConfig = proplists:get_value(formatter_config, Config, []),
+    %% the standard log handler has a file mode with size based rotation support that is much saner than
+    %% disk_log's, so use that here
+    Handler = {handler, list_to_atom(File), logger_std_h, #{level => Level,
+                                                            config => #{type => file,
+                                                                         file => filename:join(LogRoot, File),
+                                                                         max_no_files => Count,
+                                                                         max_no_bytes => Size},
+                                                            formatter =>
+                                                            {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1,
+                                                                                       formatter => Formatter,
+                                                                                       formatter_config => FormatterConfig}}}},
+    NewLevel = case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of
+                   true ->
+                       Level;
+                   false ->
+                       CurrentLevel
+               end,
+    generate_logger_handlers(Tail, {NewLevel, [Handler|Acc]}).
+
+
 %% @private
 trace_func(#trace_func_state_v1{pid=Pid, level=Level, format_string=Fmt}=FuncState, Event, ProcState) ->
     lager:log(Level, Pid, Fmt, [Event, ProcState]),

src/lager_app.erl

@@ -31,7 +31,8 @@
          start_handler/3,
          configure_sink/2,
          stop/1,
-         boot/1]).
+         boot/1,
+         default_handlers/0]).
 
 %% The `application:get_env/3` compatibility wrapper was useful
 %% for other modules in r15 and before
@@ -226,11 +227,22 @@ get_env(Application, Key, Default) ->
 
 start(_StartType, _StartArgs) ->
     {ok, Pid} = lager_sup:start_link(),
-    SavedHandlers = boot(),
-    _ = boot('__all_extra'),
-    _ = boot('__traces'),
-    clean_up_config_checks(),
-    {ok, Pid, SavedHandlers}.
+    case application:get_env(lager, lager_use_logger, false) of
+        false ->
+            SavedHandlers = boot(),
+            _ = boot('__all_extra'),
+            _ = boot('__traces'),
+            clean_up_config_checks(),
+            {ok, Pid, SavedHandlers};
+        true ->
+            case application:get_env(lager, configure_logger, false) of
+                true ->
+                    ok = lager:configure_logger();
+                false ->
+                    ok
+            end,
+            {ok, Pid}
+    end.
 
 boot() ->
     %% Handle the default sink.
@@ -276,6 +288,9 @@ stop(Handlers) ->
           error_logger:add_report_handler(Handler)
       end, Handlers).
 
+default_handlers() ->
+    ?DEFAULT_HANDLER_CONF.
+
 expand_handlers([]) ->
     [];
 expand_handlers([{lager_file_backend, [{Key, _Value}|_]=Config}|T]) when is_atom(Key) ->

src/lager_logger_formatter.erl

@@ -0,0 +1,119 @@
+-module(lager_logger_formatter).
+
+%% convert logger formatter calls into lager formatter ones
+
+-export([report_cb/1, format/2]).%, check_config/1]).
+
+report_cb(#{label := {gen_server, terminate}, name := Name, reason := Reason}) ->
+    Formatted = error_logger_lager_h:format_reason(Reason),
+    {"gen_server ~w terminated with reason: ~s", [Name, Formatted]};
+report_cb(#{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}) ->
+    Formatted = error_logger_lager_h:format_reason(Reason),
+    {"gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted]};
+report_cb(#{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}) ->
+    Formatted = error_logger_lager_h:format_reason(Reason),
+    {"gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted]};
+report_cb(#{label := {gen_statem, terminate}, name := Name, reason := Reason}) ->
+    Formatted = error_logger_lager_h:format_reason(Reason),
+    %% XXX I can't find the FSM statename in the error report, maybe it should be added
+    {"gen_statem ~w terminated with reason: ~s", [Name, Formatted]};
+report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}}) ->
+    {"undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod]};
+report_cb(#{label := {supervisor, progress}, report := Report}) ->
+    case application:get_env(lager, suppress_supervisor_start_stop, false) of
+        true ->
+            {"", []};
+        false ->
+            {supervisor, Name} = lists:keyfind(supervisor, 1, Report),
+            {started, Started} = lists:keyfind(started, 1, Report),
+            case lists:keyfind(id, 1, Started) of
+                false ->
+                    %% supervisor itself starting
+                    {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started),
+                    {pid, Pid} = lists:keyfind(pid, 1, Started),
+                    {"Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa({Module, Function, Args}), Pid]};
+                {id, ChildID} ->
+                    case lists:keyfind(pid, 1, Started) of
+                        {pid, Pid} ->
+                            {"Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid]};
+                        false ->
+                            %% children is a list of pids for some reason? and we only get the count
+                            {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started),
+                            {"Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID]}
+                    end
+            end
+    end;
+report_cb(#{label := {supervisor, _Error}, report := Report}) ->
+    {supervisor, Name} = lists:keyfind(supervisor, 1, Report),
+    {reason, Reason} = lists:keyfind(reason, 1, Report),
+    Formatted = error_logger_lager_h:format_reason(Reason),
+    {errorContext, ErrorContext} = lists:keyfind(errorContext, 1, Report),
+    {offender, Offender} = lists:keyfind(offender, 1, Report),
+    case lists:keyfind(mod, 1, Offender) of
+        {mod, _Mod} ->
+            {pid, Pid} = lists:keyfind(pid, 1, Offender),
+            %% this comes from supervisor_bridge
+            {"Supervisor ~w had ~p ~p with reason ~s", [Name, Pid, ErrorContext, Formatted]};
+        false ->
+            {id, ChildID} = lists:keyfind(id, 1, Offender),
+            case lists:keyfind(pid, 1, Offender) of
+                {pid, Pid} ->
+                    {"Supervisor ~w had ~p ~p ~p with reason ~s", [Name, ChildID, Pid, ErrorContext, Formatted]};
+                false ->
+                    {"Supervisor ~w had ~p ~p with reason ~s", [Name, ChildID, ErrorContext, Formatted]}
+            end
+    end;
+report_cb(#{label := {application_controller, progress}, report := Report}) ->
+    case application:get_env(lager, suppress_application_start_stop, false) of
+        true -> {"", []};
+        false ->
+            {application, Name} = lists:keyfind(application, 1, Report),
+            {started_at, Node} = lists:keyfind(started_at, 1, Report),
+            {"Application ~w started on node ~w", [Name, Node]}
+    end;
+report_cb(#{label := {application_controller, exit}, report := Report}) ->
+    {exited, Reason} = lists:keyfind(exited, 1, Report),
+    case application:get_env(lager, suppress_application_start_stop) of
+        {ok, true} when Reason == stopped ->
+            {"", []};
+        _ ->
+            {application, Name} = lists:keyfind(application, 1, Report),
+            Formatted = error_logger_lager_h:format_reason(Reason),
+            {"Application ~w exited with reason: ~s", [Name, Formatted]}
+    end.
+%% TODO handle proc_lib crash
+
+format(#{msg := {report, _Report}, meta := Metadata} = Event, #{report_cb := Fun} = Config) when is_function(Fun, 1); is_function(Fun, 2) ->
+    format(Event#{meta => Metadata#{report_cb => Fun}}, maps:remove(report_cb, Config));
+format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} = Event, Config) when is_function(Fun, 1) ->
+    case Fun(Report) of
+        {"", []} -> "";
+        {Format, Args} when is_list(Format), is_list(Args) ->
+            format(Event#{msg => {Format, Args}}, Config)
+    end;
+format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) ->
+    do_format(Level, String, Metadata, Config);
+format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) ->
+    Msg = lager_format:format(FmtStr, FmtArgs, maps:get(max_size, Config, 1024)),
+    do_format(Level, Msg, Metadata, Config).
+
+do_format(Level, Msg, Metadata, Config) ->
+    FormatModule = maps:get(formatter, Config, lager_default_formatter),
+    Timestamp = maps:get(time, Metadata),
+    MegaSecs = Timestamp div 1000000000000,
+    Secs = (Timestamp rem 1000000000000) div 1000000,
+    MicroSecs = (Timestamp rem 1000000000000) rem 1000000,
+    {Colors, End} = case maps:get(colors, Config, false) of
+        true ->
+                            {application:get_env(lager, colors, []), "\e[0m"};
+                        false ->
+                            {[], ""}
+                    end,
+    [FormatModule:format(lager_msg:new(Msg, {MegaSecs, Secs, MicroSecs}, Level, convert_metadata(Metadata), []), maps:get(formatter_config, Config, []), Colors), End].
+
+convert_metadata(Metadata) ->
+    maps:fold(fun(mfa, {Module, Function, Arity}, Acc) ->
+                      [{module, Module}, {function, Function}, {arity, Arity}|Acc];
+                 (K, V, Acc) ->
+                      [{K, V}|Acc]
+              end, [], Metadata).

src/lager_sup.erl

@@ -32,24 +32,29 @@ start_link() ->
     supervisor:start_link({local, ?MODULE}, ?MODULE, []).
 
 init([]) ->
-    %% set up the config, is safe even during relups
-    lager_config:new(),
-    %% TODO:
-    %% Always start lager_event as the default and make sure that
-    %% other gen_event stuff can start up as needed
-    %%
-    %% Maybe a new API to handle the sink and its policy?
-    Children = [
-        {lager, {gen_event, start_link, [{local, lager_event}]},
-            permanent, 5000, worker, dynamic},
-        {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []},
-            permanent, 5000, supervisor, [lager_handler_watcher_sup]}],
-
-    CrashLog = decide_crash_log(application:get_env(lager, crash_log, false)),
-
-    {ok, {{one_for_one, 10, 60},
-          Children ++ CrashLog
-         }}.
+    case application:get_env(lager, lager_use_logger, false) of
+        true ->
+            {ok, {{one_for_one, 10, 60}, []}};
+        false ->
+            %% set up the config, is safe even during relups
+            lager_config:new(),
+            %% TODO:
+            %% Always start lager_event as the default and make sure that
+            %% other gen_event stuff can start up as needed
+            %%
+            %% Maybe a new API to handle the sink and its policy?
+            Children = [
+                        {lager, {gen_event, start_link, [{local, lager_event}]},
+                         permanent, 5000, worker, dynamic},
+                        {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []},
+                         permanent, 5000, supervisor, [lager_handler_watcher_sup]}],
+
+            CrashLog = decide_crash_log(application:get_env(lager, crash_log, false)),
+
+            {ok, {{one_for_one, 10, 60},
+                  Children ++ CrashLog
+                 }}
+    end.
 
 validate_positive({ok, Val}, _Default) when is_integer(Val) andalso Val >= 0 ->
     Val;