test-web: Log why the test runner exits early
Log active views and tests when test-web stops before all tests have completed. Reuse the same reporting for signal handling, and accept any future signal registration without asserting while explaining shutdown. Also log observed helper process exits with decoded Unix wait status so CI logs show whether a process exited normally or died from a signal.
This commit is contained in:
parent
6aa6b0972f
commit
b71d82645b
2 changed files with 74 additions and 24 deletions
|
|
@ -12,9 +12,14 @@
|
|||
#include <AK/LexicalPath.h>
|
||||
#include <LibCore/System.h>
|
||||
|
||||
#if !defined(AK_OS_WINDOWS)
|
||||
# include <sys/wait.h>
|
||||
#endif
|
||||
|
||||
namespace TestWeb {
|
||||
|
||||
static ByteString format_elapsed_time(UnixDateTime run_start_time);
|
||||
static ByteString format_exit_status(Optional<int> exit_status);
|
||||
static void setup_capture_notifier(RefPtr<Core::Notifier>& notifier, int fd, bool drain_available, Function<void(StringView)> on_output);
|
||||
static bool drain_capture_output(int fd, bool drain_available, Function<void(StringView)> const& on_output);
|
||||
|
||||
|
|
@ -30,6 +35,7 @@ TestRunCapture::TestRunCapture()
|
|||
};
|
||||
m_previous_on_process_exited = move(process_manager.on_process_exited);
|
||||
process_manager.on_process_exited = [this](WebView::Process&& process, Optional<int> exit_status) {
|
||||
outln("test-web: observed {} process {} exit: {}", WebView::process_name_from_type(process.type()), process.pid(), format_exit_status(exit_status));
|
||||
consume_helper_capture(process.pid());
|
||||
m_previous_on_process_exited(move(process), exit_status);
|
||||
};
|
||||
|
|
@ -102,6 +108,24 @@ void TestRunCapture::log_helper_message(HelperOutputSource source, int tee_fd, S
|
|||
m_helper_output.write(message);
|
||||
}
|
||||
|
||||
static ByteString format_exit_status(Optional<int> exit_status)
|
||||
{
|
||||
if (!exit_status.has_value())
|
||||
return "unknown status"sv;
|
||||
|
||||
#if defined(AK_OS_WINDOWS)
|
||||
return ByteString::formatted("status {}", *exit_status);
|
||||
#else
|
||||
if (WIFEXITED(*exit_status))
|
||||
return ByteString::formatted("status {}", WEXITSTATUS(*exit_status));
|
||||
if (WIFSIGNALED(*exit_status))
|
||||
return ByteString::formatted("signal {}", WTERMSIG(*exit_status));
|
||||
if (WIFSTOPPED(*exit_status))
|
||||
return ByteString::formatted("stopped by signal {}", WSTOPSIG(*exit_status));
|
||||
return ByteString::formatted("raw wait status {}", *exit_status);
|
||||
#endif
|
||||
}
|
||||
|
||||
void TestRunCapture::setup_output_capture_for_view(TestWebView& view, ViewOutputCapture& view_capture)
|
||||
{
|
||||
auto process = Application::the().find_process(view.web_content_pid());
|
||||
|
|
|
|||
|
|
@ -52,6 +52,7 @@ namespace TestWeb {
|
|||
|
||||
static Vector<ViewDisplayState> s_view_display_states;
|
||||
static Vector<Function<void()>> s_view_run_next_test;
|
||||
static HashMap<WebView::ViewImplementation const*, size_t> s_view_index_by_view;
|
||||
|
||||
static RefPtr<Core::Promise<Empty>> s_all_tests_complete;
|
||||
static Vector<ByteString> s_skipped_tests;
|
||||
|
|
@ -203,6 +204,33 @@ static ErrorOr<void> collect_ref_tests(Application const& app, Vector<Test>& tes
|
|||
return {};
|
||||
}
|
||||
|
||||
static void log_active_test_views(StringView reason)
|
||||
{
|
||||
outln();
|
||||
outln("test-web: {}", reason);
|
||||
outln("test-web: active views:");
|
||||
|
||||
auto now = UnixDateTime::now();
|
||||
WebView::ViewImplementation::for_each_view([&](WebView::ViewImplementation const& view) {
|
||||
pid_t pid = 0;
|
||||
if (auto view_index = s_view_index_by_view.get(&view); view_index.has_value() && *view_index < s_view_display_states.size())
|
||||
pid = s_view_display_states[*view_index].pid;
|
||||
|
||||
out(" - View {} (pid {}): ", view.view_id(), pid);
|
||||
|
||||
auto maybe_index = s_current_test_index_by_view.get(&view);
|
||||
if (maybe_index.has_value() && s_run_context) {
|
||||
auto const& test = s_run_context->tests[*maybe_index];
|
||||
outln("{} (duration: {})", test.relative_path, human_readable_time(now - test.start_time));
|
||||
} else {
|
||||
outln("{} (no active test)", view.url());
|
||||
}
|
||||
|
||||
return IterationDecision::Continue;
|
||||
});
|
||||
outln();
|
||||
}
|
||||
|
||||
static ErrorOr<void> collect_screenshot_tests(Application const& app, Vector<Test>& tests, StringView path, StringView trail)
|
||||
{
|
||||
Core::DirIterator it(ByteString::formatted("{}/input/{}", path, trail), Core::DirIterator::Flags::SkipDots);
|
||||
|
|
@ -1194,6 +1222,7 @@ static ErrorOr<int> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePix
|
|||
for (auto [i, view] : enumerate(views)) {
|
||||
s_view_display_states[i].pid = view->web_content_pid();
|
||||
s_view_display_states[i].active = false;
|
||||
s_view_index_by_view.set(view.ptr(), i);
|
||||
}
|
||||
|
||||
display.begin_run();
|
||||
|
|
@ -1342,6 +1371,12 @@ static ErrorOr<int> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePix
|
|||
auto result_or_rejection
|
||||
= s_all_tests_complete->await();
|
||||
display.clear_live_display();
|
||||
|
||||
if (result_or_rejection.is_error())
|
||||
log_active_test_views(ByteString::formatted("test run stopped early: {}", result_or_rejection.error()));
|
||||
else if (tests_remaining > 0)
|
||||
log_active_test_views(ByteString::formatted("event loop stopped with {} unfinished tests", tests_remaining));
|
||||
|
||||
display.print_run_complete(tests, non_passing_tests, result_or_rejection.is_error() ? tests_remaining : 0);
|
||||
|
||||
if (app.dump_gc_graph) {
|
||||
|
|
@ -1370,37 +1405,28 @@ static ErrorOr<int> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePix
|
|||
|
||||
static void handle_signal(int signal)
|
||||
{
|
||||
VERIFY(signal == SIGINT || signal == SIGTERM);
|
||||
|
||||
// Quit our event loop. This makes `::exec()` return as soon as possible, and signals to WebView::Application that
|
||||
// we should no longer automatically restart processes in `::process_did_exit()`.
|
||||
Core::EventLoop::current().quit(0);
|
||||
|
||||
// Report current view statuses
|
||||
dbgln();
|
||||
dbgln("{} received. Active test views:", signal == SIGINT ? "SIGINT"sv : "SIGTERM"sv);
|
||||
dbgln();
|
||||
StringView signal_name = "signal received"sv;
|
||||
if (signal == SIGINT)
|
||||
signal_name = "SIGINT received"sv;
|
||||
else if (signal == SIGTERM)
|
||||
signal_name = "SIGTERM received"sv;
|
||||
|
||||
auto now = UnixDateTime::now();
|
||||
WebView::ViewImplementation::for_each_view([&](WebView::ViewImplementation const& view) {
|
||||
dbg("- View {}: ", view.view_id());
|
||||
|
||||
auto maybe_index = s_current_test_index_by_view.get(&view);
|
||||
if (maybe_index.has_value() && s_run_context) {
|
||||
auto const& test = s_run_context->tests[*maybe_index];
|
||||
dbgln("{} (duration: {})", test.relative_path, human_readable_time(now - test.start_time));
|
||||
} else {
|
||||
dbgln("{} (no active test)", view.url());
|
||||
}
|
||||
|
||||
return IterationDecision::Continue;
|
||||
});
|
||||
dbgln();
|
||||
if (signal == SIGINT || signal == SIGTERM)
|
||||
log_active_test_views(signal_name);
|
||||
else
|
||||
log_active_test_views(ByteString::formatted("signal {} received", signal));
|
||||
|
||||
// Stop running tests
|
||||
s_all_tests_complete->reject(signal == SIGINT
|
||||
? Error::from_string_view("SIGINT received"sv)
|
||||
: Error::from_string_view("SIGTERM received"sv));
|
||||
if (signal == SIGINT)
|
||||
s_all_tests_complete->reject(Error::from_string_view("SIGINT received"sv));
|
||||
else if (signal == SIGTERM)
|
||||
s_all_tests_complete->reject(Error::from_string_view("SIGTERM received"sv));
|
||||
else
|
||||
s_all_tests_complete->reject(Error::from_string_literal("Unexpected signal received"));
|
||||
}
|
||||
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in a new issue