From 0d125432b4a33c0f4ef1e179e60a8e842125227c Mon Sep 17 00:00:00 2001 From: Micael Karlberg Date: Fri, 5 Apr 2019 18:12:15 +0200 Subject: [snmp|agent|test] Timestamps and test manager Added common (formated) timestamp function(s). Made use of these in the verbosity module (for debug printouts) and in the test suite(s). I also *think* I found the cause for some if the test case failures (timeouts). For v3 (agent) test cases the test manager makes use of parts of the agent code: snmp_framework_mib and snmp_user_based_sm_mib. And since they store their data in snmpa_local_db, that also needs to be running. And this was the problem (I think). On some (slow) machines, the snmpa_local_db process from the *previous* test case might still be running when the we tried to start it. That meant that no new snmpa_local_db was started. Instead the old one, still running but terminating, was retain. For a while. Until it actually finally stopped. So the next operation towards snmpa_local_db, insert, simply hanged until the process terminated. This in combination with the fact that the packet server process, which was started using proc_lib, previously called init_ack before this init was actually done, could actually start and then at a much later time hang because some operation timed out (the packet server was hanging). Yuckety yuck-yuck. --- lib/snmp/src/agent/snmpa_local_db.erl | 1 + lib/snmp/src/misc/snmp_misc.erl | 118 +++++++++++++++++++++++++++++++++- lib/snmp/src/misc/snmp_verbosity.erl | 13 +--- lib/snmp/test/snmp_test_lib.erl | 15 ++--- lib/snmp/test/snmp_test_mgr_misc.erl | 71 ++++++++++++++++++-- 5 files changed, 189 insertions(+), 29 deletions(-) (limited to 'lib') diff --git a/lib/snmp/src/agent/snmpa_local_db.erl b/lib/snmp/src/agent/snmpa_local_db.erl index 0231977c46..f481641242 100644 --- a/lib/snmp/src/agent/snmpa_local_db.erl +++ b/lib/snmp/src/agent/snmpa_local_db.erl @@ -153,6 +153,7 @@ do_init(Prio, DbDir, DbInitError, Opts) -> Dets = dets_open(DbDir, DbInitError, Opts), Ets = ets:new(?ETS_TAB, [set, protected]), ?vdebug("started",[]), + put(started, snmp_misc:formated_timestamp()), {ok, #state{dets = Dets, ets = Ets}}. dets_open(DbDir, DbInitError, Opts) -> diff --git a/lib/snmp/src/misc/snmp_misc.erl b/lib/snmp/src/misc/snmp_misc.erl index 1f847b7a29..0cc04d4056 100644 --- a/lib/snmp/src/misc/snmp_misc.erl +++ b/lib/snmp/src/misc/snmp_misc.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2015. All Rights Reserved. +%% Copyright Ericsson AB 1996-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -64,8 +64,18 @@ strip_extension_from_filename/2, str_xor/2, time/3, - - verify_behaviour/2 + + verify_behaviour/2, + + %% These are used both for debugging (verbosity printouts) + %% and other such "utility" operations. + format_timestamp/1, format_timestamp/2, + format_short_timestamp/1, format_short_timestamp/2, + format_long_timestamp/1, format_long_timestamp/2, + formated_timestamp/0, + formated_short_timestamp/0, + formated_long_timestamp/0 + ]). @@ -112,6 +122,108 @@ now(sec) -> erlang:monotonic_time(seconds). + +%% --------------------------------------------------------------------------- +%% # formated_timstamp/0, formated_timstamp/1 +%% # format_short_timstamp/0, format_short_timstamp/1 +%% # format_long_timstamp/0, format_long_timstamp/1 +%% +%% Create a formatted timestamp. Short means that it will not include +%% the date in the formatted timestamp. Also it will only include millis. +%% --------------------------------------------------------------------------- + +formated_timestamp() -> + formated_long_timestamp(). + +formated_short_timestamp() -> + format_short_timestamp(os:timestamp()). + +formated_long_timestamp() -> + format_long_timestamp(os:timestamp()). + + +%% --------------------------------------------------------------------------- +%% # format_timstamp/1, format_timstamp/2 +%% # format_short_timstamp/1, format_short_timstamp/2 +%% # format_long_timstamp/1, format_long_timstamp/2 +%% +%% Formats the provided timestamp. Short means that it will not include +%% the date in the formatted timestamp. +%% --------------------------------------------------------------------------- + +-spec format_timestamp(Now :: os:timestamp()) -> + string(). + +format_timestamp(Now) -> + format_long_timestamp(Now). + +-spec format_short_timestamp(Now :: os:timestamp()) -> + string(). + +format_short_timestamp(Now) -> + N2T = fun(N) -> calendar:now_to_local_time(N) end, + format_timestamp(short, Now, N2T). + +-spec format_long_timestamp(Now :: os:timestamp()) -> + string(). + +format_long_timestamp(Now) -> + N2T = fun(N) -> calendar:now_to_local_time(N) end, + format_timestamp(long, Now, N2T). + +-spec format_timestamp(Now :: os:timestamp(), + N2T :: function()) -> + string(). + +format_timestamp(Now, N2T) when is_tuple(Now) andalso is_function(N2T) -> + format_long_timestamp(Now, N2T). + +-spec format_short_timestamp(Now :: os:timestamp(), + N2T :: function()) -> + string(). + +format_short_timestamp(Now, N2T) when is_tuple(Now) andalso is_function(N2T) -> + format_timestamp(short, Now, N2T). + +-spec format_long_timestamp(Now :: os:timestamp(), + N2T :: function()) -> + string(). + +format_long_timestamp(Now, N2T) when is_tuple(Now) andalso is_function(N2T) -> + format_timestamp(long, Now, N2T). + +format_timestamp(Format, {_N1, _N2, N3} = Now, N2T) -> + {Date, Time} = N2T(Now), + do_format_timestamp(Format, Date, Time, N3). + %% case Format of + %% short -> + %% do_format_short_timestamp(Time, N3); + %% long -> + %% do_format_long_timestamp(Date, Time, N3) + %% end. + +do_format_timestamp(short, Date, Time, N3) -> + do_format_short_timestamp(Time, N3); +do_format_timestamp(long, Date, Time, N3) -> + do_format_long_timestamp(Date, Time, N3). + +do_format_long_timestamp(Date, Time, N3) -> + {YYYY,MM,DD} = Date, + {Hour,Min,Sec} = Time, + FormatDate = + io_lib:format("~.4w-~.2.0w-~.2.0w ~.2.0w:~.2.0w:~.2.0w.~.3.0w", + [YYYY, MM, DD, Hour, Min, Sec, N3 div 1000]), + lists:flatten(FormatDate). + +do_format_short_timestamp(Time, N3) -> + {Hour,Min,Sec} = Time, + FormatDate = + io_lib:format("~.2.0w:~.2.0w:~.2.0w.~.3.0w", + [Hour, Min, Sec, N3 div 1000]), + lists:flatten(FormatDate). + + + is_crypto_supported(Alg) -> %% The 'try catch' handles the case when 'crypto' is %% not present in the system (or not started). diff --git a/lib/snmp/src/misc/snmp_verbosity.erl b/lib/snmp/src/misc/snmp_verbosity.erl index bca4bad283..9b2676d048 100644 --- a/lib/snmp/src/misc/snmp_verbosity.erl +++ b/lib/snmp/src/misc/snmp_verbosity.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2000-2015. All Rights Reserved. +%% Copyright Ericsson AB 2000-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -70,16 +70,7 @@ print2(_Verbosity,Format,Arguments) -> timestamp() -> - format_timestamp(os:timestamp()). - -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 ~w", - [YYYY,MM,DD,Hour,Min,Sec,round(N3/1000)]), - lists:flatten(FormatDate). + snmp_misc:formated_timestamp(). process_args([], Acc) -> lists:reverse(Acc); diff --git a/lib/snmp/test/snmp_test_lib.erl b/lib/snmp/test/snmp_test_lib.erl index 4973630ea2..33f7b89974 100644 --- a/lib/snmp/test/snmp_test_lib.erl +++ b/lib/snmp/test/snmp_test_lib.erl @@ -607,7 +607,8 @@ p(F, A) when is_list(F) andalso is_list(A) -> %% This is just a bog standard printout, with a (formatted) timestamp %% prefix and a newline after. -%% print1 prints to both standard_ío and to user. print2 just to standard_ío. +%% print1 - prints to both standard_io and user. +%% print2 - prints to just standard_io. print_format(F, A) -> FTS = snmp_test_lib:formated_timestamp(), @@ -629,13 +630,5 @@ print(Prefix, Module, Line, Format, Args) -> Prefix, node(), self(), Module, Line|Args]). formated_timestamp() -> - format_timestamp(os:timestamp()). - -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.~w", - [YYYY, MM, DD, Hour, Min, Sec, round(N3/1000)]), - lists:flatten(FormatDate). + snmp_misc:formated_timestamp(). + diff --git a/lib/snmp/test/snmp_test_mgr_misc.erl b/lib/snmp/test/snmp_test_mgr_misc.erl index badbbad894..315e3ebd9e 100644 --- a/lib/snmp/test/snmp_test_mgr_misc.erl +++ b/lib/snmp/test/snmp_test_mgr_misc.erl @@ -604,6 +604,13 @@ init_usm('version-3', Dir) -> ?vlog("init_usm -> create (and init) fake \"agent\" table", []), ets:new(snmp_agent_table, [set, public, named_table]), ets:insert(snmp_agent_table, {agent_mib_storage, persistent}), + %% The local-db process may *still* be running (from a previous + %% test case), on the way down, but not yet dead. + %% Either way, before we start it, make sure its dead and *gone*! + %% How do we do that without getting hung up? Calling the stop + %% function, will not do since it uses Timeout=infinity. + ?vlog("init_usm -> ensure (old) fake local-db is dead", []), + ensure_local_db_dead(), ?vlog("init_usm -> try start fake local-db", []), case snmpa_local_db:start_link(normal, Dir, [{sname, "MGR-LOCAL-DB"}, @@ -612,8 +619,12 @@ init_usm('version-3', Dir) -> ?vlog("started: ~p" "~n ~p", [Pid, process_info(Pid)]); {error, {already_started, Pid}} -> + LDBInfo = process_info(Pid), ?vlog("already started: ~p" - "~n ~p", [Pid, process_info(Pid)]) + "~n ~p", [Pid, LDBInfo]), + ?FAIL({still_running, snmpa_local_db, LDBInfo}); + {error, Reason} -> + ?FAIL({failed_starting, snmpa_local_db, Reason}) end, NameDb = snmpa_agent:db(snmpEngineID), ?vlog("init_usm -> try set manager engine-id", []), @@ -630,6 +641,60 @@ init_usm('version-3', Dir) -> init_usm(_Vsn, _Dir) -> ok. +ensure_local_db_dead() -> + ensure_dead(whereis(snmpa_local_db), 2000). + +ensure_dead(Pid, Timeout) when is_pid(Pid) -> + MRef = erlang:monitor(process, Pid), + try + begin + ensure_dead_wait(Pid, MRef, Timeout), + ensure_dead_stop(Pid, MRef, Timeout), + ensure_dead_kill(Pid, MRef, Timeout), + exit(failed_stop_local_db) + end + catch + throw:ok -> + ok + end; +ensure_dead(_, _) -> + ?vlog("ensure_dead -> already dead", []), + ok. + +ensure_dead_wait(Pid, MRef, Timeout) -> + receive + {'DOWN', MRef, process, Pid, _Info} -> + ?vlog("ensure_dead_wait -> died peacefully", []), + throw(ok) + after Timeout -> + ?vlog("ensure_dead_wait -> giving up", []), + ok + end. + +ensure_dead_stop(Pid, MRef, Timeout) -> + StopPid = spawn(fun() -> snmpa_local_db:stop() end), + receive + {'DOWN', MRef, process, Pid, _Info} -> + ?vlog("ensure_dead -> dead (stopped)", []), + throw(ok) + after Timeout -> + ?vlog("ensure_dead_stop -> giving up", []), + exit(StopPid, kill), + ok + end. + +ensure_dead_kill(Pid, MRef, Timeout) -> + exit(Pid, kill), + receive + {'DOWN', MRef, process, Pid, _Info} -> + ?vlog("ensure_dead -> dead (killed)", []), + throw(ok) + after Timeout -> + ?vlog("ensure_dead_kill -> giving up", []), + ok + end. + + display_incomming_message(M) -> display_message("Incomming",M). @@ -831,6 +896,4 @@ d(_,_F,_A) -> print(F, A) -> ?PRINT2("MGR_PS " ++ F, A). - -formated_timestamp() -> - snmp_test_lib:formated_timestamp(). + -- cgit v1.2.3