Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Switch from lager to built in logger #99

Closed
wants to merge 5 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 21 additions & 1 deletion priv/app.config
Original file line number Diff line number Diff line change
@@ -1 +1,21 @@
[{ssl, [{session_cb, amoc_always_null_ssl_session_cache}]}].
%% -*-erlang-*-

[
{kernel, [
{logger_level, warning},
{logger,
[{handler, default, logger_std_h,
#{formatter => {amoc_lager_logger_formatter,
#{report_cb => fun amoc_lager_logger_formatter:report_cb/1}}}
},
{handler, logfile, logger_std_h,
#{config => #{file => "log/console.log"},
formatter => {amoc_lager_logger_formatter,
#{report_cb => fun amoc_lager_logger_formatter:report_cb/1}}}
}
]}]},
{lager, [
{lager_use_logger, true}
]},
{ssl, [{session_cb, amoc_always_null_ssl_session_cache}]}
].
3 changes: 2 additions & 1 deletion rebar.config
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,13 @@
warn_missing_spec,
{i, ["include"]},
{src_dirs, ["src", "scenarios"]},
{lager_use_logger, true},
{parse_transform, lager_transform}]}.

{eunit_compile_opts, [nowarn_missing_spec]}.

{deps, [
{lager, "3.6.8"},
{lager, {git, "git://github.com/erlang-lager/lager", {branch, "adt/lager_use_logger-option"}}},
{jiffy, "0.15.2"},
{trails, "2.1.0"},
{cowboy_swagger, "2.1.0"},
Expand Down
6 changes: 4 additions & 2 deletions rebar.lock
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,10 @@
{<<"gun">>,{pkg,<<"gun">>,<<"1.3.0">>},1},
{<<"jiffy">>,{pkg,<<"jiffy">>,<<"0.15.2">>},0},
{<<"jsx">>,{pkg,<<"jsx">>,<<"2.9.0">>},1},
{<<"lager">>,{pkg,<<"lager">>,<<"3.6.8">>},0},
{<<"lager">>,
{git,"git://github.com/erlang-lager/lager",
{ref,"3c275e4399a1b8f8cb3434c46b9135909e865762"}},
0},
{<<"meck">>,{pkg,<<"meck">>,<<"0.8.12">>},0},
{<<"mustache">>,
{git,"https://github.com/mojombo/mustache.erl.git",
Expand Down Expand Up @@ -82,7 +85,6 @@
{<<"gun">>, <<"18E5D269649C987AF95AEC309F68A27FFC3930531DD227A6EAA0884D6684286E">>},
{<<"jiffy">>, <<"DE266C390111FD4EA28B9302F0BC3D7472468F3B8E0ACEABFBEFA26D08CD73B7">>},
{<<"jsx">>, <<"D2F6E5F069C00266CAD52FB15D87C428579EA4D7D73A33669E12679E203329DD">>},
{<<"lager">>, <<"897EFC7679BB82383448646C96768CDC4E747464DD18B999C7AACA485686B0DA">>},
{<<"meck">>, <<"1F7B1A9F5D12C511848FEC26BBEFD09A21E1432EADB8982D9A8ACEB9891A3CF2">>},
{<<"proper">>, <<"C1ACD51C51DA17A2FE91D7A6FC6A0C25A6A9849D8DC77093533109D1218D8457">>},
{<<"quickrand">>, <<"E3086A153EB13A057FC19192D05E2D4C6BB2BDBB55746A699BEAE9847AC17CA8">>},
Expand Down
3 changes: 2 additions & 1 deletion src/amoc_api_scenario_handler.erl
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
to_json/2,
from_json/2]).

-include_lib("kernel/include/logger.hrl").

-record(state, {resource, users}).

Expand Down Expand Up @@ -176,7 +177,7 @@ get_result(Result) ->
true -> started;
false ->
Errors = lists:filter(fun(X) -> X =/= ok end, Result),
lager:error("Run scenario error: ~p", [Errors]),
?LOG_ERROR("Run scenario error: ~p", [Errors]),
error
end.

Expand Down
14 changes: 8 additions & 6 deletions src/amoc_config.erl
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,8 @@
-type error() :: invalid_settings() | invalid_module.
-type invalid_settings() :: {invalid_settings, [{name(), value(), reason()}]}.

-include_lib("kernel/include/logger.hrl").

%% ------------------------------------------------------------------
%% API
%% ------------------------------------------------------------------
Expand Down Expand Up @@ -84,13 +86,13 @@ get_value_and_verify({Name, DefaultValue, VerificationMethod}) ->
Verification = case {DefaultValueVerification, ValueVerification} of
{true, true} -> true;
{false, true} ->
lager:error("Invalid default value for ~p", [Name]),
?LOG_ERROR("Invalid default value for ~p", [Name]),
{false, bad_default_value};
{true, false} ->
lager:error("Invalid value for ~p", [Name]),
?LOG_ERROR("Invalid value for ~p", [Name]),
{false, bad_value};
{false, false} ->
lager:error("Invalid value & default value for ~p", [Name]),
?LOG_ERROR("Invalid value & default value for ~p", [Name]),
{false, bad_value_bad_default_value}
end,
{Name, NewValue, Verification}.
Expand All @@ -113,19 +115,19 @@ verify_value(Value, [_ | _] = NonemptyList) ->
verify_value(Value, Fun) when is_function(Fun, 1) ->
call_verify_fun(Fun,Value);
verify_value(_, VerificationMethod) ->
lager:error("invalid verification method ~p", [VerificationMethod]),
?LOG_ERROR("invalid verification method ~p", [VerificationMethod]),
false.

call_verify_fun(Fun, Value) ->
try Fun(Value) of
Bool when is_boolean(Bool) -> Bool;
{true, NewValue} -> {true, NewValue};
Ret ->
lager:error("invalid verification method ~p, return value : ~p", [Fun, Ret]),
?LOG_ERROR("invalid verification method ~p, return value : ~p", [Fun, Ret]),
false
catch
C:E:S ->
lager:error("invalid verification method ~p, exception: ~p ~p ~p", [Fun, C, E, S]),
?LOG_ERROR("invalid verification method ~p, exception: ~p ~p ~p", [Fun, C, E, S]),
false
end.

Expand Down
28 changes: 15 additions & 13 deletions src/amoc_controller.erl
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,8 @@
-type interarrival() :: non_neg_integer().
-type user_batch_strategy() :: [{node(), user_count(), interarrival()}].

-include_lib("kernel/include/logger.hrl").

%% ------------------------------------------------------------------
%% Types Exports
%% ------------------------------------------------------------------
Expand Down Expand Up @@ -196,7 +198,7 @@ code_change(_OldVsn, State, _Extra) ->
-spec handle_add(user_count(), state(), proplists:proplist()) ->
ok | list({ok, pid()}).
handle_add(_Count, #state{scenario=undefined}, _Opts) ->
lager:error("add users invoked, but no scenario defined");
?LOG_ERROR("add users invoked, but no scenario defined");
handle_add(Count, #state{scenario=Scenario,
scenario_state=State,
nodes = Nodes,
Expand All @@ -212,7 +214,7 @@ handle_add(Count, #state{scenario=Scenario,

-spec handle_remove(user_count(), amoc:remove_opts(), state()) -> ok.
handle_remove(_Count, _Opts, #state{scenario=undefined}) ->
lager:error("remove users invoked, but no scenario defined");
?LOG_ERROR("remove users invoked, but no scenario defined");
handle_remove(Count, Opts, _State) when
is_integer(Count), Count > 0 ->
ForceRemove = proplists:get_value(force, Opts, false),
Expand Down Expand Up @@ -247,12 +249,12 @@ handle_do(Scenario, UserIds, State) ->
scenario_state = ScenarioState},
{reply, ok, State1};
{error, Reason} ->
lager:error("scenario ~p initialisation failed, reason: ~p",
?LOG_ERROR("scenario ~p initialisation failed, reason: ~p",
[Scenario, Reason]),
{reply, {error, Reason}, State}
end;
Error ->
lager:error("scenario module ~p cannot be found, reason: ~p",
?LOG_ERROR("scenario module ~p cannot be found, reason: ~p",
[Scenario, Error]),
{reply, {error, Error}, State}
end.
Expand All @@ -264,10 +266,10 @@ handle_check(Scenario, Interval) ->
schedule_scenario_checking(Scenario, Interval),
continue;
{ok, {stop, Reason}} ->
lager:info("scenario should be terminated, reason=~p", [Reason]),
?LOG_INFO("scenario should be terminated, reason=~p", [Reason]),
try_terminate_scenario(Scenario, Reason);
{error, Error, Reason} ->
lager:error("continue/1 callback failed, scenario should be"
?LOG_ERROR("continue/1 callback failed, scenario should be"
" terminated, error=~p, reason=~p", [Error, Reason]),
try_terminate_scenario(Scenario, {Error, Reason})
end.
Expand All @@ -284,7 +286,7 @@ handle_add_batch(Scenario, BatchCount, CurrentBatch, PrevUserCount, Interval) ->
maybe_schedule_add_batch({Scenario, BatchCount - 1, CurrentBatch + 1,
TotalUserCount}, Interval);
{error, Error, Reason} ->
lager:error("next_user_batch/2 callback failed, scenario should be"
?LOG_ERROR("next_user_batch/2 callback failed, scenario should be"
" terminated, error=~p, reason=~p", [Error, Reason]),
try_terminate_scenario(Scenario, {Error, Reason})
end.
Expand All @@ -299,7 +301,7 @@ start_scenario(Scenario, UserIds, State) ->
Start = lists:min(UserIds),
End = lists:max(UserIds),
Length = erlang:length(UserIds),
lager:info("starting scenario begin_id=~p, end_id=~p, length=~p",
?LOG_INFO("starting scenario begin_id=~p, end_id=~p, length=~p",
[Start, End, Length]),
start_users(Scenario, UserIds, interarrival(), State).

Expand All @@ -321,10 +323,10 @@ maybe_start_scenario_checking(Scenario) ->
case are_callbacks_exported(Scenario, Callbacks) of
true ->
schedule_scenario_checking(Scenario, checking_interval()),
lager:info("checking has been started", []),
?LOG_INFO("checking has been started", []),
ok;
false ->
lager:info("checking is not started as callbacks=~p are not"
?LOG_INFO("checking is not started as callbacks=~p are not"
" exported", [Callbacks]),
skip
end.
Expand All @@ -339,7 +341,7 @@ maybe_add_batches(Scenario, BatchCount, CurrentBatch, PrevUserCount) ->
PrevUserCount}, add_batch_interval()),
ok;
false ->
lager:info("add batches is not possible as callbacks=~p are not"
?LOG_INFO("add batches is not possible as callbacks=~p are not"
" exported", [Callbacks]),
skip
end.
Expand All @@ -357,7 +359,7 @@ are_callbacks_exported(Scenario, Callbacks) ->
erlang:function_exported(Scenario, Func, Arity)
end, Callbacks);
Error ->
lager:error("scenario module ~p cannot be found, reason: ~p",
?LOG_ERROR("scenario module ~p cannot be found, reason: ~p",
[Scenario, Error]),
false
end.
Expand All @@ -383,7 +385,7 @@ try_terminate_scenario(Scenario, Reason) ->
{ok, _} ->
ok;
{error, E, R} ->
lager:error("terminate/1 callback failed, scenario cannot be"
?LOG_ERROR("terminate/1 callback failed, scenario cannot be"
" terminated, error=~p, reason=~p", [E, R]),
application:stop(amoc)
end.
Expand Down
129 changes: 129 additions & 0 deletions src/amoc_lager_logger_formatter.erl
Original file line number Diff line number Diff line change
@@ -0,0 +1,129 @@
%% This module is copied from: https://github.com/erlang-lager/lager/blob/adt/lager_use_logger-option/src/lager_logger_formatter.erl
%% with amendments. Original comments left intact.
%% Fixed timestamp formatting, added catch all clause for report_cb.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we contribute back the timestamp fix?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or all the changes? I think we'll need this formatter in other places like amoc-arsenal-xmpp and possibly MongooseIM. It's better to use one file instead of coping it to every repo.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The whole thing is quite controversial. Maybe I focused on the wrong thing which is the seamless combination of lager and logger.

Unfortunately the integration of the two by the lager author Andrew Thompson is left not quite finished. It seems to work, but it is in a feature branch of lager, not promoted to a release (as the author announced at his presentation this spring in SF - https://codesync.global/media/erlang-logging-for-the-21st-otp-andrew-thompson/).
Given the state of affairs I wouldn't recommend including lager_logger integration in Mongoose yet, let's wait for the next release of Lager).

Should we include it in Amoc at all? Well perhaps as a way of testing it, for example performance and be prepared for the final version.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Based on this issue erlang-lager/lager#519 I think the author may need some external help to get this integration moving. I think we can try contributing the fixes and see if they get accepted.


-module(amoc_lager_logger_formatter).

%% convert logger formatter calls into lager formatter ones

-export([report_cb/1, format/2]).%, check_config/1]).

-spec report_cb(lager:report()) -> {io:format(),[term()]}.
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;
report_cb(Other) ->
{"Unexpected logger report_cb: ~w", [Other]}.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As far as I know this is our addition to the formater, right? I think it makes unexpected logs unreadable in some case. For instance I have this error (it's my fault in Erlang and docsh configuration) printed by pure logger:

(amoc@MichalPiotrowski-MacBookPro2018)1> 09:25:05.869 [error] file:path_eval(["/Users/michalpiotrowski"],".erlang"): error on line 50: 50: evaluation failed with reason error:undef and stacktrace [{docsh,activated,[path],[]},{erl_eval,do_apply,6,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,680}]},{erl_eval,exprs,5,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,126}]},{erl_eval,expr,5,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,462}]},{file,eval_stream2,6,[{file,[102,105,108,101,46,101,114,108]},{line,1393}]},{file,path_eval,3,[{file,[102,105,108,101,46,101,114,108]},{line,1059}]},{c,f_p_e,2,[{file,[99,46,101,114,108]},{line,693}]},{init,eval_script,2,[]}]

Which is readable and I know what to do about it. When the lager/logger integration is enabled the above log looks like the following:

2019-10-30 09:54:30.965 [error] <0.8.0> Unexpected logger report_cb: #{args => [[[47,85,115,101,114,115,47,109,105,99,104,97,108,112,105,111,116,114,111,119,115,107,105]],[46,101,114,108,97,110,103],50,[[53,48],58,32,101,118,97,108,117,97,116,105,111,110,32,102,97,105,108,101,100,32,119,105,116,104,32,114,101,97,115,111,110,32,[101,114,114,111,114],58,[117,110,100,101,102],32,97,110,100,32,115,116,97,99,107,116,114,97,99,101,32,[91,[[123,[[100,111,99,115,104],44,[97,99,116,105,118,97,116,101,100],44,[91,[[112,97,116,104]],93],44,[91,93]],125],44,[123,[[101,114,108,95,101,118,97,108],44,[100,111,95,97,112,112,108,121],44,[54],44,[91,[[123,[[102,105,108,101],44,[91,[[49,48,49],44,[49,49,52],44,[49,48,56],44,[57,53],44,[49,48,49],44,[49,49,56],44,[57,55],44,[49,48,56],44,[52,54],44,[49,48,49],44,[49,49,52],44,[49,48,56]],93]],125],44,[123,[[108,105,110,101],44,[54,56,48]],125]],93]],125],44,[123,[[101,114,108,95,101,118,97,108],44,[101,120,112,114,115],44,[53],44,[91,[[123,[[102,105,108,101],44,[91,[[49,48,49],44,[49,...],...],...]],...],...],...]],...],...],...]]],...}

This is very cryptic and it's close to impossible to figure out what's wrong.

Current master branch of Amoc produces the same output as my first example.

I'm not sure if trying to unify lager and logger logs makes sense, at least for Amoc.

%% TODO handle proc_lib crash

-spec format(LogEvent, Config) -> unicode:chardata() when
LogEvent :: logger:log_event(),
Config :: term(). %% see: lib/kernel/src/logger_formatter.erl for config definition
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).
4 changes: 3 additions & 1 deletion src/amoc_metrics.erl
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,8 @@
-export([update_time/2, update_counter/2, update_counter/1, update_gauge/2]).
-export([messages_spiral_name/0, message_ttd_histogram_name/0]).

-include_lib("kernel/include/logger.hrl").

-type simple_name() :: atom() | [atom()].

-type name() :: simple_name() | {strict, simple_name()}.
Expand Down Expand Up @@ -119,6 +121,6 @@ maybe_subscribe(ExName, Datapoints) ->
exometer_report:unsubscribe(Reporter, ExName, Datapoints),
ok = exometer_report:subscribe(Reporter, ExName, Datapoints, Interval);
_ ->
lager:warning("Reporter=~p not_enbled", [Reporter])
?LOG_WARNING("Reporter=~p not_enbled", [Reporter])
end.

Loading