From aa0cb115b78730dc5c72282df4f3d1114a157a58 Mon Sep 17 00:00:00 2001 From: Micael Karlberg Date: Thu, 20 Jun 2019 16:37:51 +0200 Subject: [megaco|test] Make sure more of the (mess) test suite printouts are shown Make the test suite log more readable. Normal io and the debug printouts from megaco does not mix well. Its difficult to know the proper timeline. So add some "sleeps" so that its easier to read. --- lib/megaco/test/megaco_mess_test.erl | 59 +++++++++++++++++++++--------------- lib/megaco/test/megaco_test_lib.hrl | 2 ++ 2 files changed, 36 insertions(+), 25 deletions(-) (limited to 'lib') diff --git a/lib/megaco/test/megaco_mess_test.erl b/lib/megaco/test/megaco_mess_test.erl index 7af6f26bf1..d3216c2a6d 100644 --- a/lib/megaco/test/megaco_mess_test.erl +++ b/lib/megaco/test/megaco_mess_test.erl @@ -597,6 +597,7 @@ request_and_no_reply(Config) when is_list(Config) -> ET = [{text,tcp}, {text,udp}, {binary,tcp}, {binary,udp}], {ok, Mgc} = ?MGC_START(MgcNode, {deviceName, "ctrl"}, ET, [], ?MGC_VERBOSITY), + ?SLEEP(?SECONDS(1)), i("[MG] start"), Mg1Mid = {deviceName, "mg1"}, @@ -621,9 +622,13 @@ request_and_no_reply(Config) when is_list(Config) -> {pending_timer, PendingTmr}, {reply_timer, ReplyTmr}], {ok, Mg1} = ?MG_START(Mg1Node, Mg1Mid, text, tcp, MgConfig, ?MG_VERBOSITY), + ?SLEEP(?SECONDS(1)), {ok, Mg2} = ?MG_START(Mg2Node, Mg2Mid, text, udp, MgConfig, ?MG_VERBOSITY), + ?SLEEP(?SECONDS(1)), {ok, Mg3} = ?MG_START(Mg3Node, Mg3Mid, binary, tcp, MgConfig, ?MG_VERBOSITY), + ?SLEEP(?SECONDS(1)), {ok, Mg4} = ?MG_START(Mg4Node, Mg4Mid, binary, udp, MgConfig, ?MG_VERBOSITY), + ?SLEEP(?SECONDS(1)), d("MG1 user info: ~p", [?MG_USER_INFO(Mg1, all)]), d("MG1 conn info: ~p", [?MG_CONN_INFO(Mg1, all)]), @@ -639,55 +644,68 @@ request_and_no_reply(Config) when is_list(Config) -> d("service change result: ~p", [ServChRes1]), d("MG1 user info: ~p", [?MG_USER_INFO(Mg1, all)]), d("MG1 conn info: ~p", [?MG_CONN_INFO(Mg1, all)]), + ?SLEEP(?SECONDS(1)), i("[MG2] connect to the MGC (service change)"), ServChRes2 = ?MG_SERV_CHANGE(Mg2), d("service change result: ~p", [ServChRes2]), d("MG2 user info: ~p", [?MG_USER_INFO(Mg2, all)]), d("MG2 conn info: ~p", [?MG_CONN_INFO(Mg2, all)]), + ?SLEEP(?SECONDS(1)), i("[MG3] connect to the MGC (service change)"), ServChRes3 = ?MG_SERV_CHANGE(Mg3), d("service change result: ~p", [ServChRes3]), d("MG3 user info: ~p", [?MG_USER_INFO(Mg3, all)]), d("MG3 conn info: ~p", [?MG_CONN_INFO(Mg3, all)]), + ?SLEEP(?SECONDS(1)), i("[MG4] connect to the MGC (service change)"), ServChRes4 = ?MG_SERV_CHANGE(Mg4), d("service change result: ~p", [ServChRes4]), d("MG4 user info: ~p", [?MG_USER_INFO(Mg4, all)]), d("MG4 conn info: ~p", [?MG_CONN_INFO(Mg4, all)]), + ?SLEEP(?SECONDS(1)), d("tell the MGC to ignore requests"), ?MGC_REQ_PEND(Mgc, infinity), + ?SLEEP(?SECONDS(1)), d("[MG1] send the notify"), ?MG_NOTIF_REQ(Mg1), + ?SLEEP(?SECONDS(1)), d("[MG2] send the notify"), ?MG_NOTIF_REQ(Mg2), + ?SLEEP(?SECONDS(1)), d("[MG3] send the notify"), ?MG_NOTIF_REQ(Mg3), + ?SLEEP(?SECONDS(1)), d("[MG4] send the notify"), ?MG_NOTIF_REQ(Mg4), + ?SLEEP(?SECONDS(1)), d("[MG1] await notify reply"), {ok, {_Vsn1, {error, timeout}}} = ?MG_AWAIT_NOTIF_REP(Mg1), d("[MG1] received expected reply"), + ?SLEEP(?SECONDS(1)), d("[MG2] await notify reply"), {ok, {_Vsn2, {error, timeout}}} = ?MG_AWAIT_NOTIF_REP(Mg2), d("[MG2] received expected reply"), + ?SLEEP(?SECONDS(1)), d("[MG3] await notify reply"), {ok, {_Vsn3, {error, timeout}}} = ?MG_AWAIT_NOTIF_REP(Mg3), d("[MG3] received expected reply"), + ?SLEEP(?SECONDS(1)), d("[MG4] await notify reply"), {ok, {_Vsn4, {error, timeout}}} = ?MG_AWAIT_NOTIF_REP(Mg4), d("[MG4] received expected reply"), + ?SLEEP(?SECONDS(1)), d("MG1 user info: ~p", [?MG_USER_INFO(Mg1, all)]), d("MG1 conn info: ~p", [?MG_CONN_INFO(Mg1, all)]), @@ -13711,38 +13729,36 @@ i(F) -> i(F, []). i(F, A) -> - print(info, get(verbosity), now(), get(tc), "INF", F, A). + print(info, "INF", F, A). d(F) -> d(F, []). d(F, A) -> - print(debug, get(verbosity), now(), get(tc), "DBG", F, A). + print(debug, "DBG", F, A). -printable(_, debug) -> true; -printable(info, info) -> true; -printable(_,_) -> false. +print(Severity, PRE, FMT, ARGS) -> + print(Severity, get(verbosity), erlang:timestamp(), get(tc), PRE, FMT, ARGS). print(Severity, Verbosity, Ts, Tc, P, F, A) -> print(printable(Severity,Verbosity), Ts, Tc, P, F, A). -print(true, Ts, Tc, P, F, A) -> - io:format("*** [~s] ~s ~p ~s:~w ***" - "~n " ++ F ++ "~n", - [format_timestamp(Ts), P, self(), get(sname), Tc | A]); +print(true, TS, TC, P, F, A) -> + S = ?F("*** [~s] ~s ~p ~s:~w ***" + "~n " ++ F ++ "~n", + [megaco:format_timestamp(TS), P, self(), get(sname), TC | A]), + io:format("~s", [S]), + io:format(user, "~s", [S]); print(_, _, _, _, _, _) -> ok. -format_timestamp({_N1, _N2, N3} = Now) -> - {Date, Time} = calendar:now_to_datetime(Now), - {YYYY,MM,DD} = Date, - {Hour,Min,Sec} = Time, - FormatDate = - io_lib:format("~.4w:~.2.0w:~.2.0w ~.2.0w:~.2.0w:~.2.0w 4~w", - [YYYY,MM,DD,Hour,Min,Sec,round(N3/1000)]), - lists:flatten(FormatDate). + +printable(_, debug) -> true; +printable(info, info) -> true; +printable(_,_) -> false. + %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% @@ -13752,13 +13768,6 @@ to(To, Start) -> %% Time in milli seconds mtime() -> - {A,B,C} = erlang:now(), + {A,B,C} = erlang:timestamp(), A*1000000000+B*1000+(C div 1000). -%% random_init() -> -%% {A,B,C} = now(), -%% random:seed(A,B,C). - -%% random() -> -%% 10 * random:uniform(50). - diff --git a/lib/megaco/test/megaco_test_lib.hrl b/lib/megaco/test/megaco_test_lib.hrl index b198619e2a..19103c0a79 100644 --- a/lib/megaco/test/megaco_test_lib.hrl +++ b/lib/megaco/test/megaco_test_lib.hrl @@ -32,6 +32,8 @@ -define(ERROR(Reason), megaco_test_lib:error(Reason, ?MODULE, ?LINE)). +-define(F(FMT, ARGS), lists:flatten(io_lib:format(FMT, ARGS))). + -define(OS_BASED_SKIP(Skippable), megaco_test_lib:os_based_skip(Skippable)). -- cgit v1.2.3 From 6afac8386a0feefab34126997a064a631af8b40a Mon Sep 17 00:00:00 2001 From: Micael Karlberg Date: Tue, 25 Jun 2019 12:57:03 +0200 Subject: [megaco|test] Attempt to avoid race on slow VMs --- lib/megaco/test/megaco_examples_test.erl | 2 +- lib/megaco/test/megaco_mib_test.erl | 4 ++-- lib/megaco/test/megaco_test_lib.hrl | 3 ++- lib/megaco/test/megaco_timer_test.erl | 11 ++--------- 4 files changed, 7 insertions(+), 13 deletions(-) (limited to 'lib') diff --git a/lib/megaco/test/megaco_examples_test.erl b/lib/megaco/test/megaco_examples_test.erl index 815e315c27..10ca0375f6 100644 --- a/lib/megaco/test/megaco_examples_test.erl +++ b/lib/megaco/test/megaco_examples_test.erl @@ -357,6 +357,6 @@ d(F, A) -> d(get(dbg), F, A). d(true, F, A) -> - io:format("DBG: ~s " ++ F ++ "~n", [?FT() | A]); + io:format("DBG: ~s " ++ F ++ "~n", [?FTS() | A]); d(_, _F, _A) -> ok. diff --git a/lib/megaco/test/megaco_mib_test.erl b/lib/megaco/test/megaco_mib_test.erl index a19e2acbd1..06ac7c08ed 100644 --- a/lib/megaco/test/megaco_mib_test.erl +++ b/lib/megaco/test/megaco_mib_test.erl @@ -1714,7 +1714,7 @@ print(Severity, Verbosity, P, F, A) -> print(printable(Severity,Verbosity), P, F, A). print(true, P, F, A) -> - io:format("~s~p:~s:~s: " ++ F ++ "~n", [P, self(), get(sname), ?FT() | A]); + io:format("~s~p:~s:~s: " ++ F ++ "~n", [P, self(), get(sname), ?FTS() | A]); print(_, _, _, _) -> ok. @@ -1723,7 +1723,7 @@ progress(F) -> progress(F, []). progress(F, A) -> - io:format(user, "~s " ++ F ++ "~n", [?FT()|A]). + io:format(user, "~s " ++ F ++ "~n", [?FTS()|A]). %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% diff --git a/lib/megaco/test/megaco_test_lib.hrl b/lib/megaco/test/megaco_test_lib.hrl index 19103c0a79..409f8d52e5 100644 --- a/lib/megaco/test/megaco_test_lib.hrl +++ b/lib/megaco/test/megaco_test_lib.hrl @@ -85,4 +85,5 @@ -define(HOURS(T), megaco_test_lib:hours(T)). -define(MINUTES(T), megaco_test_lib:minutes(T)). -define(SECONDS(T), megaco_test_lib:seconds(T)). --define(FT(), megaco_test_lib:formated_timestamp()). +-define(FTS(), megaco:format_timestamp(erlang:timestamp())). + diff --git a/lib/megaco/test/megaco_timer_test.erl b/lib/megaco/test/megaco_timer_test.erl index b60e8581cd..d3e8e27636 100644 --- a/lib/megaco/test/megaco_timer_test.erl +++ b/lib/megaco/test/megaco_timer_test.erl @@ -332,7 +332,7 @@ integer_timer_start_and_expire(Config) when is_list(Config) -> receive {timeout, Timeout} -> ok - after Timeout + 100 -> + after Timeout + 500 -> tmr_stop(Ref), error(no_timeout) end, @@ -443,13 +443,6 @@ print1(_, _, _, _) -> print(Prefix, F, A) -> io:format("*** [~s] ~s ~p ~s:~w ***" "~n " ++ F ++ "~n", - [formated_timestamp(), Prefix, self(), get(sname), get(tc) | A]). + [?FTS(), Prefix, self(), get(sname), get(tc) | A]). - - - -%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% - -formated_timestamp() -> - megaco:format_timestamp(os:timestamp()). -- cgit v1.2.3