Merge pull request #397 from erlang-lager/feature/log-metadata-from-error-logger

Capture error-site metadata from error_logger messages & feed them to lager

src/error_logger_lager_h.erl

@@ -148,20 +148,23 @@ log_event(Event, #state{sink=Sink} = State) ->
                     %% gen_server terminate
                     [Name, _Msg, _State, Reason] = Args,
                     ?CRASH_LOG(Event),
-                    ?LOGFMT(Sink, error, Pid, "gen_server ~w terminated with reason: ~s",
-                        [Name, format_reason(Reason)]);
+                    {Md, Formatted} = format_reason_md(Reason),
+                    ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_server ~w terminated with reason: ~s",
+                        [Name, Formatted]);
                 {false, "** State machine "++_} ->
                     %% gen_fsm terminate
                     [Name, _Msg, StateName, _StateData, Reason] = Args,
+                    {Md, Formatted} = format_reason_md(Reason),
                     ?CRASH_LOG(Event),
-                    ?LOGFMT(Sink, error, Pid, "gen_fsm ~w in state ~w terminated with reason: ~s",
-                        [Name, StateName, format_reason(Reason)]);
+                    ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_fsm ~w in state ~w terminated with reason: ~s",
+                        [Name, StateName, Formatted]);
                 {false, "** gen_event handler"++_} ->
                     %% gen_event handler terminate
                     [ID, Name, _Msg, _State, Reason] = Args,
+                    {Md, Formatted} = format_reason_md(Reason),
                     ?CRASH_LOG(Event),
-                    ?LOGFMT(Sink, error, Pid, "gen_event ~w installed in ~w terminated with reason: ~s",
-                        [ID, Name, format_reason(Reason)]);
+                    ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_event ~w installed in ~w terminated with reason: ~s",
+                        [ID, Name, Formatted]);
                 {false, "** Cowboy handler"++_} ->
                     %% Cowboy HTTP server error
                     ?CRASH_LOG(Event),
@@ -174,27 +177,31 @@ log_event(Event, #state{sink=Sink} = State) ->
                         [Module, Function, Arity, _Class, Reason | Tail] ->
                             %% any other cowboy error_format list *always* ends with the stacktrace
                             StackTrace = lists:last(Tail),
-                            ?LOGFMT(Sink, error, Pid,
+                            {Md, Formatted} = format_reason_md({Reason, StackTrace}),
+                            ?LOGFMT(Sink, error, [{pid, Pid} | Md],
                                 "Cowboy handler ~p terminated in ~p:~p/~p with reason: ~s",
-                                [Module, Module, Function, Arity, format_reason({Reason, StackTrace})])
+                                [Module, Module, Function, Arity, Formatted])
                     end;
                 {false, "Ranch listener "++_} ->
                     %% Ranch errors
                     ?CRASH_LOG(Event),
                     case Args of
                         [Ref, _Protocol, Worker, {[{reason, Reason}, {mfa, {Module, Function, Arity}}, {stacktrace, StackTrace} | _], _}] ->
-                            ?LOGFMT(Sink, error, Worker,
+                            {Md, Formatted} = format_reason_md({Reason, StackTrace}),
+                            ?LOGFMT(Sink, error, [{pid, Worker} | Md],
                                 "Ranch listener ~p terminated in ~p:~p/~p with reason: ~s",
-                                [Ref, Module, Function, Arity, format_reason({Reason, StackTrace})]);
+                                [Ref, Module, Function, Arity, Formatted]);
                         [Ref, _Protocol, Worker, Reason] ->
-                            ?LOGFMT(Sink, error, Worker,
+                            {Md, Formatted} = format_reason_md(Reason),
+                            ?LOGFMT(Sink, error, [{pid, Worker} | Md],
                                 "Ranch listener ~p terminated with reason: ~s",
-                                [Ref, format_reason(Reason)]);
+                                [Ref, Formatted]);
                         [Ref, Protocol, Ret] ->
                             %% ranch_conns_sup.erl module line 119-123 has three parameters error msg, log it.
-                            ?LOGFMT(Sink, error, Protocol,
+                            {Md, Formatted} = format_reason_md(Ret),
+                            ?LOGFMT(Sink, error, [{pid, Protocol} | Md],
                                 "Ranch listener ~p terminated with result:~s",
-                                [Ref, format_reason(Ret)])
+                                [Ref, Formatted])
                     end;
                 {false, "webmachine error"++_} ->
                     %% Webmachine HTTP server error
@@ -207,7 +214,8 @@ log_event(Event, #state{sink=Sink} = State) ->
                         _ ->
                             Error
                     end,
-                    ?LOGFMT(Sink, error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]);
+                    {Md, Formatted} = format_reason_md(StackTrace),
+                    ?LOGFMT(Sink, error, [{pid, Pid} | Md], "Webmachine error at path ~p : ~s", [Path, Formatted]);
                 _ ->
                     ?CRASH_LOG(Event),
                     ?LOGFMT(Sink, error, Pid, Fmt, Args)
@@ -220,15 +228,17 @@ log_event(Event, #state{sink=Sink} = State) ->
             case lists:sort(D) of
                 [{errorContext, Ctx}, {offender, Off}, {reason, Reason}, {supervisor, Name}] ->
                     Offender = format_offender(Off),
-                    ?LOGFMT(Sink, error, Pid,
+                    {Md, Formatted} = format_reason_md(Reason),
+                    ?LOGFMT(Sink, error, [{pid, Pid} | Md],
                         "Supervisor ~w had child ~s exit with reason ~s in context ~w",
-                        [supervisor_name(Name), Offender, format_reason(Reason), Ctx]);
+                        [supervisor_name(Name), Offender, Formatted, Ctx]);
                 _ ->
                     ?LOGMSG(Sink, error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D))
             end;
         {error_report, _GL, {Pid, crash_report, [Self, Neighbours]}} ->
             ?CRASH_LOG(Event),
-            ?LOGMSG(Sink, error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours));
+            {Md, Formatted} = format_crash_report(Self, Neighbours),
+            ?LOGMSG(Sink, error, [{pid, Pid} | Md], "CRASH REPORT " ++ Formatted);
         {warning_msg, _GL, {Pid, Fmt, Args}} ->
             ?LOGFMT(Sink, warning, Pid, Fmt, Args);
         {warning_report, _GL, {Pid, std_warning, Report}} ->
@@ -243,8 +253,9 @@ log_event(Event, #state{sink=Sink} = State) ->
                         {ok, true} when Reason == stopped ->
                             ok;
                         _ ->
-                            ?LOGFMT(Sink, info, Pid, "Application ~w exited with reason: ~s",
-                                    [App, format_reason(Reason)])
+                            {Md, Formatted} = format_reason_md(Reason),
+                            ?LOGFMT(Sink, info, [{pid, Pid} | Md], "Application ~w exited with reason: ~s",
+                                    [App, Formatted])
                     end;
                 _ ->
                     ?LOGMSG(Sink, info, Pid, print_silly_list(D))
@@ -287,14 +298,23 @@ format_crash_report(Report, Neighbours) ->
             get_value(pid, Report);
         Atom -> Atom
     end,
+    Md0 = case get_value(dictionary, Report, []) of
+        [] ->
+            %% process_info(Pid, registered_name) returns [] for unregistered processes
+            [];
+        Dict ->
+            %% pull the lager metadata out of the process dictionary, if we can
+            get_value('_lager_metadata', Dict, [])
+    end,
+
     {Class, Reason, Trace} = get_value(error_info, Report),
-    ReasonStr = format_reason({Reason, Trace}),
+    {Md, ReasonStr} = format_reason_md({Reason, Trace}),
     Type = case Class of
         exit -> "exited";
         _ -> "crashed"
     end,
-    io_lib:format("Process ~w with ~w neighbours ~s with reason: ~s",
-        [Name, length(Neighbours), Type, ReasonStr]).
+    {Md0 ++ Md, io_lib:format("Process ~w with ~w neighbours ~s with reason: ~s",
+        [Name, length(Neighbours), Type, ReasonStr])}.
 
 format_offender(Off) ->
     case get_value(mfargs, Off) of
@@ -304,7 +324,7 @@ format_offender(Off) ->
                 [get_value(mod, Off), get_value(pid, Off)]);
         MFArgs ->
             %% regular supervisor
-            MFA = format_mfa(MFArgs),
+            {_, MFA} = format_mfa_md(MFArgs),
 
             %% In 2014 the error report changed from `name' to
             %% `id', so try that first.
@@ -318,40 +338,73 @@ format_offender(Off) ->
                 [Name, MFA, get_value(pid, Off)])
     end.
 
-format_reason({'function not exported', [{M, F, A},MFA|_]}) ->
-    ["call to undefined function ", format_mfa({M, F, length(A)}),
-        " from ", format_mfa(MFA)];
-format_reason({'function not exported', [{M, F, A, _Props},MFA|_]}) ->
+%% backwards compatability shim
+format_reason(Reason) ->
+    element(2, format_reason_md(Reason)).
+
+-spec format_reason_md(Stacktrace:: any()) -> {Metadata:: [{atom(), any()}], String :: list()}.
+format_reason_md({'function not exported', [{M, F, A},MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {_, Formatted2} = format_mfa_md({M, F, length(A)}),
+    {[{reason, 'function not exported'} | Md],
+     ["call to undefined function ", Formatted2,
+         " from ", Formatted]};
+format_reason_md({'function not exported', [{M, F, A, _Props},MFA|_]}) ->
     %% R15 line numbers
-    ["call to undefined function ", format_mfa({M, F, length(A)}),
-        " from ", format_mfa(MFA)];
-format_reason({undef, [MFA|_]}) ->
-    ["call to undefined function ", format_mfa(MFA)];
-format_reason({bad_return, {_MFA, {'EXIT', Reason}}}) ->
-    format_reason(Reason);
-format_reason({bad_return, {MFA, Val}}) ->
-    ["bad return value ", print_val(Val), " from ", format_mfa(MFA)];
-format_reason({bad_return_value, Val}) ->
-    ["bad return value: ", print_val(Val)];
-format_reason({{bad_return_value, Val}, MFA}) ->
-    ["bad return value: ", print_val(Val), " in ", format_mfa(MFA)];
-format_reason({{badrecord, Record}, [MFA|_]}) ->
-    ["bad record ", print_val(Record), " in ", format_mfa(MFA)];
-format_reason({{case_clause, Val}, [MFA|_]}) ->
-    ["no case clause matching ", print_val(Val), " in ", format_mfa(MFA)];
-format_reason({function_clause, [MFA|_]}) ->
-    ["no function clause matching ", format_mfa(MFA)];
-format_reason({if_clause, [MFA|_]}) ->
-    ["no true branch found while evaluating if expression in ", format_mfa(MFA)];
-format_reason({{try_clause, Val}, [MFA|_]}) ->
-    ["no try clause matching ", print_val(Val), " in ", format_mfa(MFA)];
-format_reason({badarith, [MFA|_]}) ->
-    ["bad arithmetic expression in ", format_mfa(MFA)];
-format_reason({{badmatch, Val}, [MFA|_]}) ->
-    ["no match of right hand value ", print_val(Val), " in ", format_mfa(MFA)];
-format_reason({emfile, _Trace}) ->
-    "maximum number of file descriptors exhausted, check ulimit -n";
-format_reason({system_limit, [{M, F, _}|_] = Trace}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {_, Formatted2} = format_mfa_md({M, F, length(A)}),
+    {[{reason, 'function not exported'} | Md],
+     ["call to undefined function ", Formatted2,
+         " from ", Formatted]};
+format_reason_md({undef, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, undef} | Md],
+     ["call to undefined function ", Formatted]};
+format_reason_md({bad_return, {_MFA, {'EXIT', Reason}}}) ->
+    format_reason_md(Reason);
+format_reason_md({bad_return, {MFA, Val}}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, bad_return} | Md],
+     ["bad return value ", print_val(Val), " from ", Formatted]};
+format_reason_md({bad_return_value, Val}) ->
+    {[{reason, bad_return}],
+     ["bad return value: ", print_val(Val)]};
+format_reason_md({{bad_return_value, Val}, MFA}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, bad_return_value} | Md],
+     ["bad return value: ", print_val(Val), " in ", Formatted]};
+format_reason_md({{badrecord, Record}, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badrecord} | Md],
+     ["bad record ", print_val(Record), " in ", Formatted]};
+format_reason_md({{case_clause, Val}, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, case_clause} | Md],
+     ["no case clause matching ", print_val(Val), " in ", Formatted]};
+format_reason_md({function_clause, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, function_clause} | Md],
+     ["no function clause matching ", Formatted]};
+format_reason_md({if_clause, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, if_clause} | Md],
+     ["no true branch found while evaluating if expression in ", Formatted]};
+format_reason_md({{try_clause, Val}, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, try_clause} | Md],
+     ["no try clause matching ", print_val(Val), " in ", Formatted]};
+format_reason_md({badarith, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badarith} | Md],
+     ["bad arithmetic expression in ", Formatted]};
+format_reason_md({{badmatch, Val}, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badmatch} | Md],
+     ["no match of right hand value ", print_val(Val), " in ", Formatted]};
+format_reason_md({emfile, _Trace}) ->
+    {[{reason, emfile}],
+     "maximum number of file descriptors exhausted, check ulimit -n"};
+format_reason_md({system_limit, [{M, F, _}|_] = Trace}) ->
     Limit = case {M, F} of
         {erlang, open_port} ->
             "maximum number of ports exceeded";
@@ -367,57 +420,81 @@ format_reason({system_limit, [{M, F, _}|_] = Trace}) ->
             {Str, _} = lager_trunc_io:print(Trace, 500),
             Str
     end,
-    ["system limit: ", Limit];
-format_reason({badarg, [MFA,MFA2|_]}) ->
+    {[{reason, system_limit}], ["system limit: ", Limit]};
+format_reason_md({badarg, [MFA,MFA2|_]}) ->
     case MFA of
         {_M, _F, A, _Props} when is_list(A) ->
             %% R15 line numbers
-            ["bad argument in call to ", format_mfa(MFA), " in ", format_mfa(MFA2)];
+            {Md, Formatted} = format_mfa_md(MFA2),
+            {_, Formatted2} = format_mfa_md(MFA),
+            {[{reason, badarg} | Md],
+             ["bad argument in call to ", Formatted2, " in ", Formatted]};
         {_M, _F, A} when is_list(A) ->
-            ["bad argument in call to ", format_mfa(MFA), " in ", format_mfa(MFA2)];
+            {Md, Formatted} = format_mfa_md(MFA2),
+            {_, Formatted2} = format_mfa_md(MFA),
+            {[{reason, badarg} | Md],
+             ["bad argument in call to ", Formatted2, " in ", Formatted]};
         _ ->
             %% seems to be generated by a bad call to a BIF
-            ["bad argument in ", format_mfa(MFA)]
+            {Md, Formatted} = format_mfa_md(MFA),
+            {[{reason, badarg} | Md],
+             ["bad argument in ", Formatted]}
     end;
-format_reason({{badarg, Stack}, _}) ->
-    format_reason({badarg, Stack});
-format_reason({{badarity, {Fun, Args}}, [MFA|_]}) ->
+format_reason_md({{badarg, Stack}, _}) ->
+    format_reason_md({badarg, Stack});
+format_reason_md({{badarity, {Fun, Args}}, [MFA|_]}) ->
     {arity, Arity} = lists:keyfind(arity, 1, erlang:fun_info(Fun)),
-    [io_lib:format("fun called with wrong arity of ~w instead of ~w in ",
-            [length(Args), Arity]), format_mfa(MFA)];
-format_reason({noproc, MFA}) ->
-    ["no such process or port in call to ", format_mfa(MFA)];
-format_reason({{badfun, Term}, [MFA|_]}) ->
-    ["bad function ", print_val(Term), " in ", format_mfa(MFA)];
-format_reason({Reason, [{M, F, A}|_]}) when is_atom(M), is_atom(F), is_integer(A) ->
-    [format_reason(Reason), " in ", format_mfa({M, F, A})];
-format_reason({Reason, [{M, F, A, Props}|_]}) when is_atom(M), is_atom(F), is_integer(A), is_list(Props) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badarity} | Md],
+     [io_lib:format("fun called with wrong arity of ~w instead of ~w in ",
+                    [length(Args), Arity]), Formatted]};
+format_reason_md({noproc, MFA}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badarity} | Md],
+     ["no such process or port in call to ", Formatted]};
+format_reason_md({{badfun, Term}, [MFA|_]}) ->
+    {Md, Formatted} = format_mfa_md(MFA),
+    {[{reason, badfun} | Md],
+     ["bad function ", print_val(Term), " in ", Formatted]};
+format_reason_md({Reason, [{M, F, A}|_]}) when is_atom(M), is_atom(F), is_integer(A) ->
+    {Md, Formatted} = format_reason_md(Reason),
+    {_, Formatted2} = format_mfa_md({M, F, A}),
+    {Md, [Formatted, " in ", Formatted2]};
+format_reason_md({Reason, [{M, F, A, Props}|_]}) when is_atom(M), is_atom(F), is_integer(A), is_list(Props) ->
     %% line numbers
-    [format_reason(Reason), " in ", format_mfa({M, F, A, Props})];
-format_reason(Reason) ->
+    {Md, Formatted} = format_reason_md(Reason),
+    {_, Formatted2} = format_mfa_md({M, F, A, Props}),
+    {Md, [Formatted, " in ", Formatted2]};
+format_reason_md(Reason) ->
     {Str, _} = lager_trunc_io:print(Reason, 500),
-    Str.
+    {[], Str}.
+
+%% backwards compatability shim
+format_mfa(MFA) ->
+    element(2, format_mfa_md(MFA)).
 
-format_mfa({M, F, A}) when is_list(A) ->
+-spec format_mfa_md(any()) -> {[{atom(), any()}], list()}.
+format_mfa_md({M, F, A}) when is_list(A) ->
     {FmtStr, Args} = format_args(A, [], []),
-    io_lib:format("~w:~w("++FmtStr++")", [M, F | Args]);
-format_mfa({M, F, A}) when is_integer(A) ->
-    io_lib:format("~w:~w/~w", [M, F, A]);
-format_mfa({M, F, A, Props}) when is_list(Props) ->
+    {[{module, M}, {function, F}], io_lib:format("~w:~w("++FmtStr++")", [M, F | Args])};
+format_mfa_md({M, F, A}) when is_integer(A) ->
+    {[{module, M}, {function, F}], io_lib:format("~w:~w/~w", [M, F, A])};
+format_mfa_md({M, F, A, Props}) when is_list(Props) ->
     case get_value(line, Props) of
         undefined ->
-            format_mfa({M, F, A});
+            format_mfa_md({M, F, A});
         Line ->
-            [format_mfa({M, F, A}), io_lib:format(" line ~w", [Line])]
+            {Md, Formatted} = format_mfa_md({M, F, A}),
+            {[{line, Line} | Md], [Formatted, io_lib:format(" line ~w", [Line])]}
     end;
-format_mfa([{M, F, A}, _]) ->
+format_mfa_md([{M, F, A}, _]) ->
    %% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
-   format_mfa({M, F, A});
-format_mfa([{M, F, A, Props}, _]) when is_list(Props) ->
+   format_mfa_md({M, F, A});
+format_mfa_md([{M, F, A, Props}, _]) when is_list(Props) ->
    %% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
-   format_mfa({M, F, A, Props});
-format_mfa(Other) ->
-    io_lib:format("~w", [Other]).
+   format_mfa_md({M, F, A, Props});
+format_mfa_md(Other) ->
+    {[], io_lib:format("~w", [Other])}.
 
 format_args([], FmtAcc, ArgsAcc) ->
     {string:join(lists:reverse(FmtAcc), ", "), lists:reverse(ArgsAcc)};