diff --git a/src/ejabberd_app.erl b/src/ejabberd_app.erl index 93d5a7f00b..fa44ecb007 100644 --- a/src/ejabberd_app.erl +++ b/src/ejabberd_app.erl @@ -56,6 +56,7 @@ start(normal, _Args) -> ejabberd_config:start(), ejabberd_check:config(), connect_nodes(), + mongoose_deprecations:start(), {ok, _} = Sup = ejabberd_sup:start_link(), ejabberd_rdbms:start(), mongoose_riak:start(), @@ -79,6 +80,7 @@ start(_, _) -> %% This function is called when an application is about to be stopped, %% before shutting down the processes of the application. prep_stop(State) -> + mongoose_deprecations:stop(), ejabberd_listener:stop_listeners(), stop_modules(), mongoose_subhosts:stop(), diff --git a/src/mod_mam.erl b/src/mod_mam.erl index 4454a85938..66d1f6ec23 100644 --- a/src/mod_mam.erl +++ b/src/mod_mam.erl @@ -193,9 +193,9 @@ start(Host, Opts) -> case gen_mod:get_opt(add_archived_element, Opts, undefined) of undefined -> ok; _ -> - ?WARNING_MSG("Archived element is going to be deprecated in one of future releases." - " It is not recommended to use it." - " Consider using a element instead", []) + mongoose_deprecations:log(mam02, " element is going to be removed in release 3.0.0" + " It is not recommended to use it." + " Consider using a element instead") end, compile_params_module(Opts), diff --git a/src/mod_mam_muc.erl b/src/mod_mam_muc.erl index 9f5ebb643b..29dc2db5db 100644 --- a/src/mod_mam_muc.erl +++ b/src/mod_mam_muc.erl @@ -163,9 +163,9 @@ start(Host, Opts) -> case gen_mod:get_opt(add_archived_element, Opts, undefined) of undefined -> ok; _ -> - ?WARNING_MSG("Archived element is going to be deprecated in one of future releases." - " It is not recommended to use it." - " Consider using a element instead", []) + mongoose_deprecations:log(mam02, " element is going to be removed in release 3.0.0" + " It is not recommended to use it." + " Consider using a element instead") end, compile_params_module(Opts), %% MUC host. diff --git a/src/mod_mam_utils.erl b/src/mod_mam_utils.erl index 010438eeaa..941aaba259 100644 --- a/src/mod_mam_utils.erl +++ b/src/mod_mam_utils.erl @@ -237,6 +237,9 @@ maybe_add_arcid_elems(To, MessID, Packet, AddArchived, AddStanzaid) -> BareTo = jid:to_binary(jid:to_bare(To)), WithArchived = case AddArchived of true -> + mongoose_deprecations:log(mam02, " element is going to be removed in release 3.0.0" + " It is not recommended to use it." + " Consider using a element instead"), replace_arcid_elem(<<"archived">>, BareTo, MessID, Packet); _ -> Packet end, @@ -983,7 +986,6 @@ is_last_page(_PageSize, _TotalCount, _Offset, _MessageRows) -> %% Otherwise either TotalCount or Offset is undefined because of optimizations. false. - %% ----------------------------------------------------------------------- %% Ejabberd diff --git a/src/mongoose_deprecations.erl b/src/mongoose_deprecations.erl new file mode 100644 index 0000000000..ec4332a050 --- /dev/null +++ b/src/mongoose_deprecations.erl @@ -0,0 +1,128 @@ +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% File : mongoose_deprecations.erl +%% Author : Dominik Stanaszek +%% Purpose : More generic deprecation handling +%% Created : 10 Oct 2017 +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% @doc This module is responsible for initialising +%% and stopping stuff needed to handle different deprecation +%% warinings as well as for exposing API for loging these +%% deprecations. +%% It checks whether a specific deprecation warning is not exceeding +%% given frequency of logging. +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% + +-module(mongoose_deprecations). +-author("dominik.stanaszek@erlang-solutions.com"). + +-export([start/0, stop/0, log/2, log/3]). + +%% Test API +-export([log_with_lvl/2]). + +-include("ejabberd.hrl"). + +-define(DEPRECATION_TAB, deprecations). % ETS table name +-define(DEFAULT_COOLDOWN_HOURS, 6). % default cooldown time + +-type deprecation_tag() :: atom(). % Specifies the deprecation +-type log_level() :: warning | error. +-type unix_timestamp() :: mod_mam:unix_timestamp(). + + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% Public API +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% + +%% @doc Should be called before using the module. Sets everything +%% needed up +-spec start() -> ok. +start() -> + prepare_ets(), + ok. + +%% @doc Used after using the module, when we won't log deprecation +%% messages again. +-spec stop() -> ok. +stop() -> + destroy_ets(), + ok. + +%% @doc Should be used to log deprecation messages. It logs +%% keeping proper frequency. Opts can be: +%% * cooldown - the minimal interval (in milliseconds) +%% to be held between logs. Default: 6 hours +%% It is internally represented in microseconds +%% but API requires milliseconds. +%% * log_level - 'warning' or 'error' +-spec log(deprecation_tag(), string(), proplists:proplist()) -> ok. +log(Tag, Msg, Opts) -> + Cooldown = milliseconds_to_microseconds( + proplists:get_value(cooldown, Opts, default_cooldown()) + ), + LogLvl = proplists:get_value(log_level, Opts, default_log_lvl()), + maybe_log(Tag, Msg, LogLvl, Cooldown). + +-spec log(deprecation_tag(), string()) -> ok. +log(Tag, Msg) -> + log(Tag, Msg, []). + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% Private functions +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% + + +%% @doc Deprecation table will hold pairs in form: +%% {deprecation_tag(), unix_timestamp()} +%% and will indicate at what (unix) time last deprecation +%% warining was logged concerning a deprecation connected to +%% the deprecation tag specified in a key +-spec prepare_ets() -> ok. +prepare_ets() -> + ets:new(?DEPRECATION_TAB, [{read_concurrency, true}, named_table, public]), + ok. + +-spec destroy_ets() -> ok. +destroy_ets() -> + ets:delete(?DEPRECATION_TAB), + ok. + +-spec maybe_log(deprecation_tag(), string(), log_level(), unix_timestamp()) -> ok. +maybe_log(Tag, Msg, Lvl, Cooldown) -> + Timestamp = case ets:lookup(?DEPRECATION_TAB, Tag) of + [] -> + not_logged; + [{Tag, LastLogged}] -> + LastLogged + end, + case did_cooldown_elapse(Timestamp, Cooldown) of + true -> + ?MODULE:log_with_lvl(Msg, Lvl), % ?MODULE lets meck mock it + ets:insert(?DEPRECATION_TAB, {Tag, os:timestamp()}), + ok; + false -> + ok + end. + +-spec did_cooldown_elapse(unix_timestamp() | 'not_logged', unix_timestamp()) + -> boolean(). +did_cooldown_elapse(not_logged, _) -> true; +did_cooldown_elapse(LastLogged, Cooldown) -> + Now = os:timestamp(), + timer:now_diff(Now, LastLogged) > Cooldown. + +-spec default_cooldown() -> unix_timestamp(). +default_cooldown() -> ?DEFAULT_COOLDOWN_HOURS * 3600000000. + +-spec default_log_lvl() -> log_level(). +default_log_lvl() -> error. + +-spec log_with_lvl(string(), log_level()) -> ok. +log_with_lvl(Msg, error) -> + ?ERROR_MSG(Msg, []); +log_with_lvl(Msg, warning) -> + ?WARNING_MSG(Msg, []). + +-spec milliseconds_to_microseconds(Milliseconds :: integer()) + -> unix_timestamp(). +milliseconds_to_microseconds(N) -> N * 1000. diff --git a/test/mongoose_deprecations_SUITE.erl b/test/mongoose_deprecations_SUITE.erl new file mode 100644 index 0000000000..2ebfe83886 --- /dev/null +++ b/test/mongoose_deprecations_SUITE.erl @@ -0,0 +1,135 @@ +-module(mongoose_deprecations_SUITE). + +-include_lib("eunit/include/eunit.hrl"). +-include_lib("common_test/include/ct.hrl"). + +-compile([export_all]). + +-define(TEST_COOLDOWN, 50). % ms +-define(COOLDOWN_EPS, 3). % ms, must be much smaller than TEST_COOLDOWN +-define(LOG_MSG, "hey, deprecated!"). + +all() -> + [ + check_too_fast_pace, + check_ok_pace, + check_changing_pace, + different_tags_get_logged_always, + specified_lvl_logged_default_stays, + default_lvl_is_error + ]. + +init_per_suite(C) -> + C. + +end_per_suite(C) -> + C. + +init_per_testcase(_, C) -> + mock_log_with_lvl(self()), + mongoose_deprecations:start(), + C. + +end_per_testcase(_, C) -> + mongoose_deprecations:stop(), + meck:unload(), + C. + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% Test cases +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% + +check_too_fast_pace(Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, _} = assert_n_logged(1), + ok. + +check_ok_pace(_Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, _} = assert_n_logged(3), + ok. + +check_changing_pace(_Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, _} = assert_n_logged(3), + ok. + +%% Even the same message can be logged with any frequency when tags +%% are different +different_tags_get_logged_always(_Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag1, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + mongoose_deprecations:log(some_tag2, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, _} = assert_n_logged(3), + ok. + +default_lvl_is_error(_Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, [error, error, error]} = assert_n_logged(3), + ok. + +% One can specify the level error on warning. It does not affect the default +% level. +specified_lvl_logged_default_stays(_Config) -> + mongoose_deprecations:log(some_tag, ?LOG_MSG, + [{cooldown, ?TEST_COOLDOWN}, + {log_level, warning}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, + [{cooldown, ?TEST_COOLDOWN}, + {log_level, warning}]), + timer:sleep(?TEST_COOLDOWN + ?COOLDOWN_EPS), + mongoose_deprecations:log(some_tag, ?LOG_MSG, [{cooldown, ?TEST_COOLDOWN}]), + {ok, [warning, error, warning, error]} = assert_n_logged(4), + ok. + + + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% Helpers +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% + +% Returns {ok, Lvls} where Lvls is the list +% of log levels used for each message. In order +% of appearing. +assert_n_logged(N) -> + do_assert_n_logged(N, []). + +do_assert_n_logged(0, LvlsAcc) -> + receive + {logged, {Msg, Lvl}} -> + ct:fail(too_many_logged) + after ?TEST_COOLDOWN * 2 -> + {ok, lists:reverse(LvlsAcc)} + end; +do_assert_n_logged(N, LvlsAcc) -> + receive + {logged, {Msg, Lvl}} -> + do_assert_n_logged(N - 1, [Lvl | LvlsAcc]) + after ?TEST_COOLDOWN * 2 -> + ct:fail(too_little_logged) + end. + +mock_log_with_lvl(Pid) -> + meck:new(mongoose_deprecations, [passthrough]), + meck:expect(mongoose_deprecations, log_with_lvl, fun(Msg, Lvl) -> + Pid ! {logged, {Msg, Lvl}}, + ok end).