diff options
| -rw-r--r-- | test/unit_inbroker_non_parallel_SUITE.erl | 298 | ||||
| -rw-r--r-- | test/unit_log_management_SUITE.erl | 415 |
2 files changed, 415 insertions, 298 deletions
diff --git a/test/unit_inbroker_non_parallel_SUITE.erl b/test/unit_inbroker_non_parallel_SUITE.erl index 514031b97d..ae340aba71 100644 --- a/test/unit_inbroker_non_parallel_SUITE.erl +++ b/test/unit_inbroker_non_parallel_SUITE.erl @@ -40,9 +40,6 @@ groups() -> disk_monitor_enable, file_handle_cache, %% Change FHC limit. head_message_timestamp_statistics, %% Expect specific statistics. - log_management, %% Check log files. - log_file_initialised_during_startup, - log_file_fails_to_initialise_during_startup, externally_rotated_logs_are_automatically_reopened, %% Check log files. exchange_count, queue_count, @@ -342,301 +339,6 @@ file_handle_cache_reserve_monitor1(_Config) -> ?assertEqual([{files_reserved, 0}], file_handle_cache:info([files_reserved])), passed. -%% ------------------------------------------------------------------- -%% Log management. -%% ------------------------------------------------------------------- - -log_management(Config) -> - passed = rabbit_ct_broker_helpers:rpc(Config, 0, - ?MODULE, log_management1, [Config]). - -log_management1(_Config) -> - [LogFile|_] = rabbit:log_locations(), - Suffix = ".0", - - ok = test_logs_working([LogFile]), - - %% prepare basic logs - file:delete(LogFile ++ Suffix), - ok = test_logs_working([LogFile]), - - %% simple log rotation - ok = rabbit:rotate_logs(), - %% FIXME: rabbit:rotate_logs/0 is asynchronous due to a limitation - %% in Lager. Therefore, we have no choice but to wait an arbitrary - %% amount of time. - timer:sleep(2000), - [true, true] = non_empty_files([LogFile ++ Suffix, LogFile]), - ok = test_logs_working([LogFile]), - - %% log rotation on empty files - ok = clean_logs([LogFile], Suffix), - ok = rabbit:rotate_logs(), - timer:sleep(2000), - ?assertEqual([true, true], non_empty_files([LogFile ++ Suffix, LogFile])), - - %% logs with suffix are not writable - ok = rabbit:rotate_logs(), - timer:sleep(2000), - ok = make_files_non_writable([LogFile ++ Suffix]), - ok = rabbit:rotate_logs(), - timer:sleep(2000), - ok = test_logs_working([LogFile]), - - %% rotate when original log files are not writable - ok = make_files_non_writable([LogFile]), - ok = rabbit:rotate_logs(), - timer:sleep(2000), - - %% logging directed to tty (first, remove handlers) - ok = rabbit:stop(), - ok = make_files_writable([LogFile ++ Suffix]), - ok = clean_logs([LogFile], Suffix), - ok = application:set_env(rabbit, lager_default_file, tty), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - timer:sleep(200), - rabbit_log:info("test info"), - - %% rotate logs when logging is turned off - ok = rabbit:stop(), - ok = clean_logs([LogFile], Suffix), - ok = application:set_env(rabbit, lager_default_file, false), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - timer:sleep(200), - rabbit_log:error("test error"), - timer:sleep(200), - ?assertEqual([{error,enoent}], empty_files([LogFile])), - - %% cleanup - ok = rabbit:stop(), - ok = clean_logs([LogFile], Suffix), - ok = application:set_env(rabbit, lager_default_file, LogFile), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - ok = test_logs_working([LogFile]), - passed. - -log_file_initialised_during_startup(Config) -> - passed = rabbit_ct_broker_helpers:rpc(Config, 0, - ?MODULE, log_file_initialised_during_startup1, [Config]). - -log_file_initialised_during_startup1(_Config) -> - [LogFile|_] = rabbit:log_locations(), - Suffix = ".0", - - %% start application with simple tty logging - ok = rabbit:stop(), - ok = clean_logs([LogFile], Suffix), - ok = application:set_env(rabbit, lager_default_file, tty), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - - %% start application with logging to non-existing directory - NonExistent = "/tmp/non-existent/test.log", - delete_file(NonExistent), - delete_file(filename:dirname(NonExistent)), - ok = rabbit:stop(), - ok = application:set_env(rabbit, lager_default_file, NonExistent), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - - %% clean up - ok = application:set_env(rabbit, lager_default_file, LogFile), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - passed. - - -log_file_fails_to_initialise_during_startup(Config) -> - NonWritableDir = case os:type() of - {win32, _} -> "C:/Windows"; - _ -> "/" - end, - case file:open(filename:join(NonWritableDir, "test.log"), [write]) of - {error, eacces} -> - passed = rabbit_ct_broker_helpers:rpc( - Config, 0, - ?MODULE, log_file_fails_to_initialise_during_startup1, - [Config, NonWritableDir]); - {ok, Fd} -> - %% If the supposedly non-writable directory is writable - %% (e.g. we are running the testsuite on Windows as - %% Administrator), we skip this test. - file:close(Fd), - {skip, "Supposedly non-writable directory is writable"} - end. - -log_file_fails_to_initialise_during_startup1(_Config, NonWritableDir) -> - [LogFile|_] = rabbit:log_locations(), - - %% start application with logging to directory with no - %% write permissions - ok = rabbit:stop(), - - Run1 = fun() -> - NoPermission1 = filename:join(NonWritableDir, "test.log"), - delete_file(NoPermission1), - delete_file(filename:dirname(NoPermission1)), - ok = rabbit:stop(), - ok = application:set_env(rabbit, lager_default_file, NoPermission1), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - rabbit:start() - end, - - ok = try Run1() of - ok -> exit({got_success_but_expected_failure, - log_rotation_no_write_permission_dir_test}) - catch - throw:{error, {rabbit, {{cannot_log_to_file, _, _}, _}}} -> ok - end, - - %% start application with logging to a subdirectory which - %% parent directory has no write permissions - NoPermission2 = filename:join([NonWritableDir, - "non-existent", - "test.log"]), - - Run2 = fun() -> - delete_file(NoPermission2), - delete_file(filename:dirname(NoPermission2)), - case rabbit:stop() of - ok -> ok; - {error, lager_not_running} -> ok - end, - ok = application:set_env(rabbit, lager_default_file, NoPermission2), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - rabbit:start() - end, - - ok = try Run2() of - ok -> exit({got_success_but_expected_failure, - log_rotation_parent_dirs_test}) - catch - throw:{error, {rabbit, {{cannot_log_to_file, _, _}, _}}} -> ok - end, - - %% clean up - ok = application:set_env(rabbit, lager_default_file, LogFile), - application:unset_env(rabbit, log), - application:unset_env(lager, handlers), - application:unset_env(lager, extra_sinks), - ok = rabbit:start(), - passed. - -externally_rotated_logs_are_automatically_reopened(Config) -> - passed = rabbit_ct_broker_helpers:rpc(Config, 0, - ?MODULE, externally_rotated_logs_are_automatically_reopened1, [Config]). - -externally_rotated_logs_are_automatically_reopened1(_Config) -> - [LogFile|_] = rabbit:log_locations(), - - %% Make sure log file is opened - ok = test_logs_working([LogFile]), - - %% Move it away - i.e. external log rotation happened - file:rename(LogFile, [LogFile, ".rotation_test"]), - - %% New files should be created - test_logs_working/1 will check that - %% LogFile is not empty after doing some logging. And it's exactly - %% what we need to check here. - ok = test_logs_working([LogFile]), - passed. - -empty_or_nonexist_files(Files) -> - [case file:read_file_info(File) of - {ok, FInfo} -> FInfo#file_info.size == 0; - {error, enoent} -> true; - Error -> Error - end || File <- Files]. - -empty_files(Files) -> - [case file:read_file_info(File) of - {ok, FInfo} -> FInfo#file_info.size == 0; - Error -> Error - end || File <- Files]. - -non_empty_files(Files) -> - [case EmptyFile of - {error, Reason} -> {error, Reason}; - _ -> not(EmptyFile) - end || EmptyFile <- empty_files(Files)]. - -test_logs_working(LogFiles) -> - ok = rabbit_log:error("Log a test message"), - %% give the error loggers some time to catch up - timer:sleep(1000), - lists:all(fun(LogFile) -> [true] =:= non_empty_files([LogFile]) end, LogFiles), - ok. - -set_permissions(Path, Mode) -> - case file:read_file_info(Path) of - {ok, FInfo} -> file:write_file_info( - Path, - FInfo#file_info{mode=Mode}); - Error -> Error - end. - -clean_logs(Files, Suffix) -> - [begin - ok = delete_file(File), - ok = delete_file([File, Suffix]) - end || File <- Files], - ok. - -delete_file(File) -> - case file:delete(File) of - ok -> ok; - {error, enoent} -> ok; - Error -> Error - end. - -make_files_writable(Files) -> - [ok = file:write_file_info(File, #file_info{mode=8#644}) || - File <- Files], - ok. - -make_files_non_writable(Files) -> - [ok = file:write_file_info(File, #file_info{mode=8#444}) || - File <- Files], - ok. - -add_log_handlers(Handlers) -> - [ok = error_logger:add_report_handler(Handler, Args) || - {Handler, Args} <- Handlers], - ok. - -%% sasl_report_file_h returns [] during terminate -%% see: https://github.com/erlang/otp/blob/maint/lib/stdlib/src/error_logger_file_h.erl#L98 -%% -%% error_logger_file_h returns ok since OTP 18.1 -%% see: https://github.com/erlang/otp/blob/maint/lib/stdlib/src/error_logger_file_h.erl#L98 -delete_log_handlers(Handlers) -> - [ok_or_empty_list(error_logger:delete_report_handler(Handler)) - || Handler <- Handlers], - ok. - -ok_or_empty_list([]) -> - []; -ok_or_empty_list(ok) -> - ok. %% ------------------------------------------------------------------- %% Statistics. diff --git a/test/unit_log_management_SUITE.erl b/test/unit_log_management_SUITE.erl new file mode 100644 index 0000000000..8f7a069e37 --- /dev/null +++ b/test/unit_log_management_SUITE.erl @@ -0,0 +1,415 @@ +%% The contents of this file are subject to the Mozilla Public License +%% Version 1.1 (the "License"); you may not use this file except in +%% compliance with the License. You may obtain a copy of the License at +%% https://www.mozilla.org/MPL/ +%% +%% Software distributed under the License is distributed on an "AS IS" +%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the +%% License for the specific language governing rights and limitations +%% under the License. +%% +%% The Original Code is RabbitMQ. +%% +%% The Initial Developer of the Original Code is GoPivotal, Inc. +%% Copyright (c) 2011-2020 VMware, Inc. or its affiliates. All rights reserved. +%% + +-module(unit_log_management_SUITE). + +-include_lib("eunit/include/eunit.hrl"). +-include_lib("common_test/include/ct.hrl"). +-include_lib("eunit/include/eunit.hrl"). +-include_lib("kernel/include/file.hrl"). +-include_lib("amqp_client/include/amqp_client.hrl"). + +-compile(export_all). + +-define(TIMEOUT, 30000). + +all() -> + [ + {group, non_parallel_tests} + ]. + +groups() -> + [ + {non_parallel_tests, [], [ + log_management, %% Check log files. + log_file_initialised_during_startup, + log_file_fails_to_initialise_during_startup, + externally_rotated_logs_are_automatically_reopened + ]} + ]. + +%% ------------------------------------------------------------------- +%% Testsuite setup/teardown. +%% ------------------------------------------------------------------- + +init_per_suite(Config) -> + rabbit_ct_helpers:log_environment(), + rabbit_ct_helpers:run_setup_steps(Config). + +end_per_suite(Config) -> + rabbit_ct_helpers:run_teardown_steps(Config). + +init_per_group(Group, Config) -> + Config1 = rabbit_ct_helpers:set_config(Config, [ + {rmq_nodename_suffix, Group}, + {rmq_nodes_count, 2} + ]), + rabbit_ct_helpers:run_steps(Config1, + rabbit_ct_broker_helpers:setup_steps() ++ + rabbit_ct_client_helpers:setup_steps()). + +end_per_group(_Group, Config) -> + rabbit_ct_helpers:run_steps(Config, + rabbit_ct_client_helpers:teardown_steps() ++ + rabbit_ct_broker_helpers:teardown_steps()). + +init_per_testcase(Testcase, Config) -> + rabbit_ct_helpers:testcase_started(Config, Testcase). + +end_per_testcase(Testcase, Config) -> + rabbit_ct_helpers:testcase_finished(Config, Testcase). + +%% ------------------------------------------------------------------- +%% Application management. +%% ------------------------------------------------------------------- + +app_management(Config) -> + passed = rabbit_ct_broker_helpers:rpc(Config, 0, + ?MODULE, app_management1, [Config]). + +app_management1(_Config) -> + wait_for_application(rabbit), + %% Starting, stopping and diagnostics. Note that we don't try + %% 'report' when the rabbit app is stopped and that we enable + %% tracing for the duration of this function. + ok = rabbit_trace:start(<<"/">>), + ok = rabbit:stop(), + ok = rabbit:stop(), + ok = no_exceptions(rabbit, status, []), + ok = no_exceptions(rabbit, environment, []), + ok = rabbit:start(), + ok = rabbit:start(), + ok = no_exceptions(rabbit, status, []), + ok = no_exceptions(rabbit, environment, []), + ok = rabbit_trace:stop(<<"/">>), + passed. + +no_exceptions(Mod, Fun, Args) -> + try erlang:apply(Mod, Fun, Args) of _ -> ok + catch Type:Ex -> {Type, Ex} + end. + +wait_for_application(Application) -> + wait_for_application(Application, 5000). + +wait_for_application(_, Time) when Time =< 0 -> + {error, timeout}; +wait_for_application(Application, Time) -> + Interval = 100, + case lists:keyfind(Application, 1, application:which_applications()) of + false -> + timer:sleep(Interval), + wait_for_application(Application, Time - Interval); + _ -> ok + end. + + + +%% ------------------------------------------------------------------- +%% Log management. +%% ------------------------------------------------------------------- + +log_management(Config) -> + passed = rabbit_ct_broker_helpers:rpc(Config, 0, + ?MODULE, log_management1, [Config]). + +log_management1(_Config) -> + [LogFile|_] = rabbit:log_locations(), + Suffix = ".0", + + ok = test_logs_working([LogFile]), + + %% prepare basic logs + file:delete(LogFile ++ Suffix), + ok = test_logs_working([LogFile]), + + %% simple log rotation + ok = rabbit:rotate_logs(), + %% FIXME: rabbit:rotate_logs/0 is asynchronous due to a limitation + %% in Lager. Therefore, we have no choice but to wait an arbitrary + %% amount of time. + timer:sleep(2000), + [true, true] = non_empty_files([LogFile ++ Suffix, LogFile]), + ok = test_logs_working([LogFile]), + + %% log rotation on empty files + ok = clean_logs([LogFile], Suffix), + ok = rabbit:rotate_logs(), + timer:sleep(2000), + ?assertEqual([true, true], non_empty_files([LogFile ++ Suffix, LogFile])), + + %% logs with suffix are not writable + ok = rabbit:rotate_logs(), + timer:sleep(2000), + ok = make_files_non_writable([LogFile ++ Suffix]), + ok = rabbit:rotate_logs(), + timer:sleep(2000), + ok = test_logs_working([LogFile]), + + %% rotate when original log files are not writable + ok = make_files_non_writable([LogFile]), + ok = rabbit:rotate_logs(), + timer:sleep(2000), + + %% logging directed to tty (first, remove handlers) + ok = rabbit:stop(), + ok = make_files_writable([LogFile ++ Suffix]), + ok = clean_logs([LogFile], Suffix), + ok = application:set_env(rabbit, lager_default_file, tty), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + timer:sleep(200), + rabbit_log:info("test info"), + + %% rotate logs when logging is turned off + ok = rabbit:stop(), + ok = clean_logs([LogFile], Suffix), + ok = application:set_env(rabbit, lager_default_file, false), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + timer:sleep(200), + rabbit_log:error("test error"), + timer:sleep(200), + ?assertEqual([{error,enoent}], empty_files([LogFile])), + + %% cleanup + ok = rabbit:stop(), + ok = clean_logs([LogFile], Suffix), + ok = application:set_env(rabbit, lager_default_file, LogFile), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + ok = test_logs_working([LogFile]), + passed. + +log_file_initialised_during_startup(Config) -> + passed = rabbit_ct_broker_helpers:rpc(Config, 0, + ?MODULE, log_file_initialised_during_startup1, [Config]). + +log_file_initialised_during_startup1(_Config) -> + [LogFile|_] = rabbit:log_locations(), + Suffix = ".0", + + %% start application with simple tty logging + ok = rabbit:stop(), + ok = clean_logs([LogFile], Suffix), + ok = application:set_env(rabbit, lager_default_file, tty), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + + %% start application with logging to non-existing directory + NonExistent = "/tmp/non-existent/test.log", + delete_file(NonExistent), + delete_file(filename:dirname(NonExistent)), + ok = rabbit:stop(), + ok = application:set_env(rabbit, lager_default_file, NonExistent), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + + %% clean up + ok = application:set_env(rabbit, lager_default_file, LogFile), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + passed. + + +log_file_fails_to_initialise_during_startup(Config) -> + NonWritableDir = case os:type() of + {win32, _} -> "C:/Windows"; + _ -> "/" + end, + case file:open(filename:join(NonWritableDir, "test.log"), [write]) of + {error, eacces} -> + passed = rabbit_ct_broker_helpers:rpc( + Config, 0, + ?MODULE, log_file_fails_to_initialise_during_startup1, + [Config, NonWritableDir]); + {ok, Fd} -> + %% If the supposedly non-writable directory is writable + %% (e.g. we are running the testsuite on Windows as + %% Administrator), we skip this test. + file:close(Fd), + {skip, "Supposedly non-writable directory is writable"} + end. + +log_file_fails_to_initialise_during_startup1(_Config, NonWritableDir) -> + [LogFile|_] = rabbit:log_locations(), + + %% start application with logging to directory with no + %% write permissions + ok = rabbit:stop(), + + Run1 = fun() -> + NoPermission1 = filename:join(NonWritableDir, "test.log"), + delete_file(NoPermission1), + delete_file(filename:dirname(NoPermission1)), + ok = rabbit:stop(), + ok = application:set_env(rabbit, lager_default_file, NoPermission1), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + rabbit:start() + end, + + ok = try Run1() of + ok -> exit({got_success_but_expected_failure, + log_rotation_no_write_permission_dir_test}) + catch + throw:{error, {rabbit, {{cannot_log_to_file, _, _}, _}}} -> ok + end, + + %% start application with logging to a subdirectory which + %% parent directory has no write permissions + NoPermission2 = filename:join([NonWritableDir, + "non-existent", + "test.log"]), + + Run2 = fun() -> + delete_file(NoPermission2), + delete_file(filename:dirname(NoPermission2)), + case rabbit:stop() of + ok -> ok; + {error, lager_not_running} -> ok + end, + ok = application:set_env(rabbit, lager_default_file, NoPermission2), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + rabbit:start() + end, + + ok = try Run2() of + ok -> exit({got_success_but_expected_failure, + log_rotation_parent_dirs_test}) + catch + throw:{error, {rabbit, {{cannot_log_to_file, _, _}, _}}} -> ok + end, + + %% clean up + ok = application:set_env(rabbit, lager_default_file, LogFile), + application:unset_env(rabbit, log), + application:unset_env(lager, handlers), + application:unset_env(lager, extra_sinks), + ok = rabbit:start(), + passed. + +externally_rotated_logs_are_automatically_reopened(Config) -> + passed = rabbit_ct_broker_helpers:rpc(Config, 0, + ?MODULE, externally_rotated_logs_are_automatically_reopened1, [Config]). + +externally_rotated_logs_are_automatically_reopened1(_Config) -> + [LogFile|_] = rabbit:log_locations(), + + %% Make sure log file is opened + ok = test_logs_working([LogFile]), + + %% Move it away - i.e. external log rotation happened + file:rename(LogFile, [LogFile, ".rotation_test"]), + + %% New files should be created - test_logs_working/1 will check that + %% LogFile is not empty after doing some logging. And it's exactly + %% what we need to check here. + ok = test_logs_working([LogFile]), + passed. + +empty_or_nonexist_files(Files) -> + [case file:read_file_info(File) of + {ok, FInfo} -> FInfo#file_info.size == 0; + {error, enoent} -> true; + Error -> Error + end || File <- Files]. + +empty_files(Files) -> + [case file:read_file_info(File) of + {ok, FInfo} -> FInfo#file_info.size == 0; + Error -> Error + end || File <- Files]. + +non_empty_files(Files) -> + [case EmptyFile of + {error, Reason} -> {error, Reason}; + _ -> not(EmptyFile) + end || EmptyFile <- empty_files(Files)]. + +test_logs_working(LogFiles) -> + ok = rabbit_log:error("Log a test message"), + %% give the error loggers some time to catch up + timer:sleep(1000), + lists:all(fun(LogFile) -> [true] =:= non_empty_files([LogFile]) end, LogFiles), + ok. + +set_permissions(Path, Mode) -> + case file:read_file_info(Path) of + {ok, FInfo} -> file:write_file_info( + Path, + FInfo#file_info{mode=Mode}); + Error -> Error + end. + +clean_logs(Files, Suffix) -> + [begin + ok = delete_file(File), + ok = delete_file([File, Suffix]) + end || File <- Files], + ok. + +delete_file(File) -> + case file:delete(File) of + ok -> ok; + {error, enoent} -> ok; + Error -> Error + end. + +make_files_writable(Files) -> + [ok = file:write_file_info(File, #file_info{mode=8#644}) || + File <- Files], + ok. + +make_files_non_writable(Files) -> + [ok = file:write_file_info(File, #file_info{mode=8#444}) || + File <- Files], + ok. + +add_log_handlers(Handlers) -> + [ok = error_logger:add_report_handler(Handler, Args) || + {Handler, Args} <- Handlers], + ok. + +%% sasl_report_file_h returns [] during terminate +%% see: https://github.com/erlang/otp/blob/maint/lib/stdlib/src/error_logger_file_h.erl#L98 +%% +%% error_logger_file_h returns ok since OTP 18.1 +%% see: https://github.com/erlang/otp/blob/maint/lib/stdlib/src/error_logger_file_h.erl#L98 +delete_log_handlers(Handlers) -> + [ok_or_empty_list(error_logger:delete_report_handler(Handler)) + || Handler <- Handlers], + ok. + +ok_or_empty_list([]) -> + []; +ok_or_empty_list(ok) -> + ok. |