Deprecate mam02

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(),

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 <stanza-id/> element instead", [])
+            mongoose_deprecations:log(mam02, "<archived/> element is going to be removed in release 3.0.0"
+                                             " It is not recommended to use it."
+                                             " Consider using a <stanza-id/> element instead")
     end,
 
     compile_params_module(Opts),

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 <stanza-id/> element instead", [])
+            mongoose_deprecations:log(mam02, "<archived/> element is going to be removed in release 3.0.0"
+                                             " It is not recommended to use it."
+                                             " Consider using a <stanza-id/> element instead")
     end,
     compile_params_module(Opts),
     %% MUC host.

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, "<archived/> element is going to be removed in release 3.0.0"
+                                                            " It is not recommended to use it."
+                                                            " Consider using a <stanza-id/> 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
 

src/mongoose_deprecations.erl

@@ -0,0 +1,128 @@
+%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
+%% File    : mongoose_deprecations.erl
+%% Author  : Dominik Stanaszek <[email protected]>
+%% 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("[email protected]").
+
+-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.

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).