From 2cd56e27bf087a1aabc1c2d287d9d9df64ffa4e7 Mon Sep 17 00:00:00 2001 From: Nick Robinson Date: Wed, 7 Aug 2024 17:01:11 +0100 Subject: [PATCH 1/3] Store the worker id used for each run of a testitem --- src/ReTestItems.jl | 4 ++-- src/log_capture.jl | 2 +- src/macros.jl | 10 +++++----- 3 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/ReTestItems.jl b/src/ReTestItems.jl index eaf8d30d..66f82e6a 100644 --- a/src/ReTestItems.jl +++ b/src/ReTestItems.jl @@ -355,7 +355,7 @@ function _runtests_in_current_env( # we use a single TestSetupModules ctx.setups_evaled = TestSetupModules() for (i, testitem) in enumerate(testitems.testitems) - testitem.workerid[] = Libc.getpid() + push!(testitem.workerid, Libc.getpid()) testitem.eval_number[] = i run_number = 1 max_runs = 1 + max(retries, testitem.retries) @@ -527,7 +527,7 @@ function manage_worker( wait(worker) worker = robust_start_worker(proj_name, nworker_threads, worker_init_expr, ntestitems) end - testitem.workerid[] = worker.pid + push!(testitem.workerid, worker.pid) timeout = something(testitem.timeout, default_timeout) fut = remote_eval(worker, :(ReTestItems.runtestitem($testitem, GLOBAL_TEST_CONTEXT; test_end_expr=$(QuoteNode(test_end_expr)), verbose_results=$verbose_results, logs=$(QuoteNode(logs))))) max_runs = 1 + max(retries, testitem.retries) diff --git a/src/log_capture.jl b/src/log_capture.jl index 6d36ac9d..c088571a 100644 --- a/src/log_capture.jl +++ b/src/log_capture.jl @@ -133,7 +133,7 @@ end ### Logging and reporting helpers ########################################################## _on_worker() = " on worker $(Libc.getpid())" -_on_worker(ti::TestItem) = " on worker $(ti.workerid[])" +_on_worker(ti::TestItem) = " on worker $(last(ti.workerid))" _file_info(ti::Union{TestSetup,TestItem}) = string(relpath(ti.file, ti.project_root), ":", ti.line) _has_logs(ts::TestSetup) = filesize(logpath(ts)) > 0 # The path might not exist if a testsetup always throws an error and we don't get to actually diff --git a/src/macros.jl b/src/macros.jl index dbd9426f..db17d5e7 100644 --- a/src/macros.jl +++ b/src/macros.jl @@ -126,10 +126,10 @@ struct TestItem project_root::String code::Any testsetups::Vector{TestSetup} # populated by runtests coordinator - workerid::Base.RefValue{Int} # populated when the test item is scheduled - testsets::Vector{DefaultTestSet} # populated when the test item is finished running + workerid::Vector{Int} # populated each time the test item is scheduled + testsets::Vector{DefaultTestSet} # populated each time the test item is finished running + stats::Vector{PerfStats} # populated each time the test item is finished running eval_number::Base.RefValue{Int} # to keep track of how many items have been run so far - stats::Vector{PerfStats} # populated when the test item is finished running scheduled_for_evaluation::ScheduledForEvaluation # to keep track of whether the test item has been scheduled for evaluation end function TestItem(number, name, id, tags, default_imports, setups, retries, timeout, skip, file, line, project_root, code) @@ -137,10 +137,10 @@ function TestItem(number, name, id, tags, default_imports, setups, retries, time return TestItem( number, name, _id, tags, default_imports, setups, retries, timeout, skip, file, line, project_root, code, TestSetup[], - Ref{Int}(0), + Int[], DefaultTestSet[], - Ref{Int}(0), PerfStats[], + Ref{Int}(0), ScheduledForEvaluation(), ) end From 25f7425d0f1d1502ce624e1ffa6faea6e120ce9b Mon Sep 17 00:00:00 2001 From: Nick Robinson Date: Wed, 7 Aug 2024 17:08:22 +0100 Subject: [PATCH 2/3] rename variable now its plural --- src/ReTestItems.jl | 4 ++-- src/log_capture.jl | 2 +- src/macros.jl | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/ReTestItems.jl b/src/ReTestItems.jl index 66f82e6a..7dbe156d 100644 --- a/src/ReTestItems.jl +++ b/src/ReTestItems.jl @@ -355,7 +355,7 @@ function _runtests_in_current_env( # we use a single TestSetupModules ctx.setups_evaled = TestSetupModules() for (i, testitem) in enumerate(testitems.testitems) - push!(testitem.workerid, Libc.getpid()) + push!(testitem.workerids, Libc.getpid()) testitem.eval_number[] = i run_number = 1 max_runs = 1 + max(retries, testitem.retries) @@ -527,7 +527,7 @@ function manage_worker( wait(worker) worker = robust_start_worker(proj_name, nworker_threads, worker_init_expr, ntestitems) end - push!(testitem.workerid, worker.pid) + push!(testitem.workerids, worker.pid) timeout = something(testitem.timeout, default_timeout) fut = remote_eval(worker, :(ReTestItems.runtestitem($testitem, GLOBAL_TEST_CONTEXT; test_end_expr=$(QuoteNode(test_end_expr)), verbose_results=$verbose_results, logs=$(QuoteNode(logs))))) max_runs = 1 + max(retries, testitem.retries) diff --git a/src/log_capture.jl b/src/log_capture.jl index c088571a..77e795fc 100644 --- a/src/log_capture.jl +++ b/src/log_capture.jl @@ -133,7 +133,7 @@ end ### Logging and reporting helpers ########################################################## _on_worker() = " on worker $(Libc.getpid())" -_on_worker(ti::TestItem) = " on worker $(last(ti.workerid))" +_on_worker(ti::TestItem) = " on worker $(last(ti.workerids))" _file_info(ti::Union{TestSetup,TestItem}) = string(relpath(ti.file, ti.project_root), ":", ti.line) _has_logs(ts::TestSetup) = filesize(logpath(ts)) > 0 # The path might not exist if a testsetup always throws an error and we don't get to actually diff --git a/src/macros.jl b/src/macros.jl index db17d5e7..735948b4 100644 --- a/src/macros.jl +++ b/src/macros.jl @@ -126,7 +126,7 @@ struct TestItem project_root::String code::Any testsetups::Vector{TestSetup} # populated by runtests coordinator - workerid::Vector{Int} # populated each time the test item is scheduled + workerids::Vector{Int} # populated each time the test item is scheduled testsets::Vector{DefaultTestSet} # populated each time the test item is finished running stats::Vector{PerfStats} # populated each time the test item is finished running eval_number::Base.RefValue{Int} # to keep track of how many items have been run so far From 506d74401ac9a8a987ecde0dcfdd520f09262630 Mon Sep 17 00:00:00 2001 From: Nick Robinson Date: Wed, 7 Aug 2024 17:26:28 +0100 Subject: [PATCH 3/3] add test --- src/log_capture.jl | 14 +++++++------- test/log_capture.jl | 14 +++++++++++++- 2 files changed, 20 insertions(+), 8 deletions(-) diff --git a/src/log_capture.jl b/src/log_capture.jl index 77e795fc..fe24cc75 100644 --- a/src/log_capture.jl +++ b/src/log_capture.jl @@ -133,7 +133,7 @@ end ### Logging and reporting helpers ########################################################## _on_worker() = " on worker $(Libc.getpid())" -_on_worker(ti::TestItem) = " on worker $(last(ti.workerids))" +_on_worker(ti::TestItem, run_number::Int) = " on worker $(ti.workerids[run_number])" _file_info(ti::Union{TestSetup,TestItem}) = string(relpath(ti.file, ti.project_root), ":", ti.line) _has_logs(ts::TestSetup) = filesize(logpath(ts)) > 0 # The path might not exist if a testsetup always throws an error and we don't get to actually @@ -178,11 +178,11 @@ function print_errors_and_captured_logs( println(report_iob) # in :eager mode, the logs were already printed if errors_first - has_errors && _print_test_errors(report_iob, ts, _on_worker(ti)) + has_errors && _print_test_errors(report_iob, ts, _on_worker(ti, run_number)) logs != :eager && _print_captured_logs(report_iob, ti, run_number) else logs != :eager && _print_captured_logs(report_iob, ti, run_number) - has_errors && _print_test_errors(report_iob, ts, _on_worker(ti)) + has_errors && _print_test_errors(report_iob, ts, _on_worker(ti, run_number)) end if has_errors || has_logs # a newline to visually separate the report for the current test item @@ -196,13 +196,13 @@ function print_errors_and_captured_logs( return nothing end -function _print_captured_logs(io, setup::TestSetup, ti::Union{Nothing,TestItem}=nothing) +function _print_captured_logs(io, setup::TestSetup, ti::Union{Nothing,TestItem}, run_number::Int) if _has_logs(setup) ti_info = isnothing(ti) ? "" : " (dependency of $(repr(ti.name)))" printstyled(io, "Captured logs"; bold=true, color=Base.info_color()) print(io, " for test setup \"$(setup.name)\"$(ti_info) at ") printstyled(io, _file_info(setup); bold=true, color=:default) - println(io, isnothing(ti) ? _on_worker() : _on_worker(ti)) + println(io, isnothing(ti) ? _on_worker() : _on_worker(ti, run_number)) open(logpath(setup), "r") do logstore write(io, logstore) end @@ -215,14 +215,14 @@ end # will call this function only if some logs were collected or when called with `verbose_results`. function _print_captured_logs(io, ti::TestItem, run_number::Int) for setup in ti.testsetups - _print_captured_logs(io, setup, ti) + _print_captured_logs(io, setup, ti, run_number) end has_logs = _has_logs(ti, run_number) bold_text = has_logs ? "Captured Logs" : "No Captured Logs" printstyled(io, bold_text; bold=true, color=Base.info_color()) print(io, " for test item $(repr(ti.name)) at ") printstyled(io, _file_info(ti); bold=true, color=:default) - println(io, _on_worker(ti)) + println(io, _on_worker(ti, run_number)) has_logs && open(logpath(ti, run_number), "r") do logstore write(io, logstore) end diff --git a/test/log_capture.jl b/test/log_capture.jl index 78d80fb2..0e38d1ae 100644 --- a/test/log_capture.jl +++ b/test/log_capture.jl @@ -36,7 +36,10 @@ end ti = TestItem(Ref(42), "TheTestItem", "ID007", [], false, [], 0, nothing, false, "source/path", 42, ".", nothing) push!(ti.testsetups, setup1) push!(ti.testsetups, setup2) - push!(ti.testsets, Test.DefaultTestSet("dummy")) + push!(ti.testsets, Test.DefaultTestSet("dummy1")) + push!(ti.workerids, 98765) + push!(ti.testsets, Test.DefaultTestSet("dummy2")) + push!(ti.workerids, 43210) setup1.logstore[] = open(ReTestItems.logpath(setup1), "w") setup2.logstore[] = open(ReTestItems.logpath(setup2), "w") @@ -46,6 +49,15 @@ end ReTestItems.print_errors_and_captured_logs(iob, ti, 1, logs=:batched) logs = String(take!(iob)) @test contains(logs, " for test item \"TheTestItem\" at ") + @test contains(logs, " on worker 98765") + @test contains(logs, "The test item has logs") + + # Test we log the right worker id for the test run + open(io->write(io, "The test item has logs"), ReTestItems.logpath(ti, 2), "w") + ReTestItems.print_errors_and_captured_logs(iob, ti, 2, logs=:batched) + logs = String(take!(iob)) + @test contains(logs, " for test item \"TheTestItem\" at ") + @test contains(logs, " on worker 43210") @test contains(logs, "The test item has logs") open(io->write(io, "The test item has logs"), ReTestItems.logpath(ti, 1), "w")