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

Introduce log_helper, and use it in config_parser_SUITE #4239

Merged
merged 1 commit into from
Mar 11, 2024
Merged
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
70 changes: 25 additions & 45 deletions test/config_parser_SUITE.erl
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
-compile([export_all, nowarn_export_all]).

-include_lib("eunit/include/eunit.hrl").
-include("log_helper.hrl").

-define(HOST, <<"example.com">>).

Expand Down Expand Up @@ -233,8 +234,7 @@ groups() ->
incorrect_module]},
{services, [parallel], [service_domain_db,
service_mongoose_system_metrics]},
{logs, [], [no_warning_about_subdomain_patterns,
no_warning_for_resolvable_domain]}
{logs, [], log_cases()}
].

init_per_suite(Config) ->
Expand All @@ -259,11 +259,22 @@ end_per_group(dynamic_domains, _Config) ->
end_per_group(_, _Config) ->
ok.

init_per_testcase(_, Config) ->
init_per_testcase(CaseName, Config) ->
case lists:member(CaseName, log_cases()) of
true -> log_helper:set_up();
false -> ok
end,
Config.

end_per_testcase(_, _Config) ->
ok.
end_per_testcase(CaseName, _Config) ->
case lists:member(CaseName, log_cases()) of
true -> log_helper:tear_down();
false -> ok
end.

log_cases() ->
[no_warning_about_subdomain_patterns,
no_warning_for_resolvable_domain].

sample_pgsql(Config) ->
test_config_file(Config, "mongooseim-pgsql").
Expand Down Expand Up @@ -2910,64 +2921,33 @@ service_mongoose_system_metrics(_Config) ->
?err(T(#{<<"tracking_id">> => #{<<"secret">> => 666, <<"id">> => 666}})),
?err(T(#{<<"report">> => <<"maybe">>})).

%% Logs

no_warning_about_subdomain_patterns(_Config) ->
check_module_defaults(mod_vcard),
check_iqdisc(mod_vcard),
P = [modules, mod_vcard],
T = fun(Opts) -> #{<<"modules">> => #{<<"mod_vcard">> => Opts}} end,

Node = #{node => mongooseim@localhost},
logger_ct_backend:start(Node),
logger_ct_backend:capture(warning, Node),

?cfgh(P ++ [host], {prefix, <<"vjud.">>},
T(#{<<"host">> => <<"vjud.@HOST@">>})),
?assertNoLog(warning, #{what := cfg_validate_domain}),

?cfgh(P ++ [host], {fqdn, <<"vjud.test">>},
T(#{<<"host">> => <<"vjud.test">>})),

logger_ct_backend:stop_capture(Node),
logger_ct_backend:stop(Node),

FilterFun = fun(_, Msg) ->
re:run(Msg, "test") /= nomatch orelse
Copy link
Collaborator

Choose a reason for hiding this comment

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

Just getting rid of these regexes and actually doing struct matching is such a great win!

re:run(Msg, "example.com") /= nomatch
end,
Logs = logger_ct_backend:recv(FilterFun),

?assertNotEqual(0, length(Logs)),
AnyContainsExampleCom = lists:any(fun({_, Msg}) ->
re:run(Msg, "example.com") /= nomatch
end, Logs),
?eq(false, AnyContainsExampleCom).
?assertLog(warning, #{what := cfg_validate_domain, reason := nxdomain, domain := "vjud.test"}).

no_warning_for_resolvable_domain(_Config) ->
T = fun(Opts) -> #{<<"modules">> => #{<<"mod_http_upload">> => Opts}} end,
P = [modules, mod_http_upload],
RequiredOpts = #{<<"s3">> => http_upload_s3_required_opts()},

Node = #{node => mongooseim@localhost},
logger_ct_backend:start(Node),
logger_ct_backend:capture(warning, Node),

?cfgh(P ++ [host], {fqdn, <<"example.org">>},
T(RequiredOpts#{<<"host">> => <<"example.org">>})),
?assertNoLog(_, #{what := cfg_validate_domain}),

?cfgh(P ++ [host], {fqdn, <<"something.invalid">>},
T(RequiredOpts#{<<"host">> => <<"something.invalid">>})),

logger_ct_backend:stop_capture(Node),
logger_ct_backend:stop(Node),

FilterFun = fun(_, Msg) ->
re:run(Msg, "example.org") /= nomatch orelse
re:run(Msg, "something.invalid") /= nomatch
end,
Logs = logger_ct_backend:recv(FilterFun),

?assertNotEqual(0, length(Logs)),
ResolvableDomainInLogs = lists:any(fun({_, Msg}) ->
re:run(Msg, "example.org") /= nomatch
end, Logs),
?eq(false, ResolvableDomainInLogs).
?assertLog(warning, #{what := cfg_validate_domain, reason := nxdomain,
domain := "something.invalid"}).

%% Helpers for module tests

Expand Down
20 changes: 20 additions & 0 deletions test/log_helper.erl
Original file line number Diff line number Diff line change
@@ -0,0 +1,20 @@
%% Helper module for checking expected log messages
%% For assertions, see log_helper.hrl

-module(log_helper).
-compile([export_all, nowarn_export_all]).

%% Call in init_per_testcase
set_up() ->
Copy link
Contributor

Choose a reason for hiding this comment

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

just note, if doing it in parallel, it would stop working because see:

https://github.com/arcusfelis/logger_debug_h/blob/main/src/logger_debug_h.erl#L23

currently it is sequential in this case.

Copy link
Member Author

@chrzaszcz chrzaszcz Mar 11, 2024

Choose a reason for hiding this comment

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

I did indeed manage to get a fail after 1000 retries of many parallel tests. I will investigate the reason, if I have time. It only happens if I do remove handlers.
Sequential is good enough for now, but we could investigate if it's a bug. If it is the case, we could just convert this module into a simple gen_server (like logger_ct_backend), or use an ETS table. There would be only one handler, and no issue.

Have you logged the issue at OTP?

Copy link
Member Author

@chrzaszcz chrzaszcz Mar 11, 2024

Choose a reason for hiding this comment

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

Just FYI: I confirm that adding/removal of handlers is done in asynchronous processes.
An ETS-based solution with a single handler is still very short, and works as expected. I will do this in a new PR.

logger:add_handler(handler_id(), ?MODULE, #{receiver => self()}).

%% Call in end_per_testcase
tear_down() ->
logger:remove_handler(handler_id()).

%% Logger callback
log(Event, #{receiver := Receiver}) ->
Copy link
Contributor

@arcusfelis arcusfelis Mar 11, 2024

Choose a reason for hiding this comment

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

Copy link
Member Author

Choose a reason for hiding this comment

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

I wasn't aware of that tool. It looks quite complicated. I'd stick with the simple solution for now.

Receiver ! {log, Event}.

handler_id() ->
list_to_atom(pid_to_list(self())).
27 changes: 27 additions & 0 deletions test/log_helper.hrl
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
%% Assertions for expected logs. Naming follows eunit.hrl
%% For set-up and tear-down, see log_helper.erl

-define(assertNoLog(LevelPattern, MsgPattern),
case ?receiveLog(LevelPattern, MsgPattern) of
no_log -> ok;
_ -> ct:fail("Received unexpected log")
end).

-define(assertLog(LevelPattern, MsgPattern),
case ?receiveLog(LevelPattern, MsgPattern) of
no_log -> ct:fail("Expected log not received");
_ -> ok
end).

-define(receiveLog(LevelPattern, MsgPattern),
?wrap(receive
{log, #{level := Level = LevelPattern,
msg := {report, Msg = MsgPattern}}} ->
ct:log("Received ~p log: ~p", [Level, Msg]),
{Level, Msg}
after
0 -> no_log
end)).

%% Wrap in a fun to avoid unsafe variables
-define(wrap(Expr), (fun() -> Expr end)()).