Skip to content

Commit

Permalink
precompilation: capture stdout as well as stderr (#3573)
Browse files Browse the repository at this point in the history
  • Loading branch information
@IanButterworth
IanButterworth authored Aug 15, 2023
1 parent 41c9244 commit 0a4fb55
Showing 1 changed file with 22 additions and 20 deletions.
42 changes: 22 additions & 20 deletions src/API.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1276,15 +1276,15 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
end
end

stderr_outputs = Dict{Base.PkgId,String}()
std_outputs = Dict{Base.PkgId,String}()
taskwaiting = Set{Base.PkgId}()
pkgspidlocked = Dict{Base.PkgId,String}()

function monitor_stderr(pkg, iob)
function monitor_std(pkg, pipe)
try
while isopen(iob)
str = readline(iob)
stderr_outputs[pkg] = get(stderr_outputs, pkg, "") * str * "\n"
while !eof(pipe)
str = readline(pipe, keep=true)
std_outputs[pkg] = string(get(std_outputs, pkg, ""), str)
if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str)
!fancyprint && lock(print_lock) do
println(io, pkg.name, color_string(" Waiting for background task / IO / timer.", Base.warn_color()))
Expand All @@ -1293,7 +1293,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
end
if !fancyprint && in(pkg, taskwaiting)
lock(print_lock) do
println(io, str)
print(io, str)
end
end
end
Expand Down Expand Up @@ -1431,8 +1431,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
is_direct_dep = pkg in direct_deps

# stderr monitoring
iob = Base.BufferStream()
t_monitor = @async monitor_stderr(pkg, iob)
std_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true)
t_monitor = @async monitor_std(pkg, std_pipe)

_name = haskey(exts, pkg) ? string(exts[pkg], " → ", pkg.name) : pkg.name
name = is_direct_dep ? _name : string(color_string(_name, :light_black))
Expand All @@ -1452,8 +1452,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
# a functionally identical package cache (except for preferences, which may differ)
t = @elapsed ret = maybe_cachefile_lock(io, print_lock, fancyprint, pkg, pkgspidlocked) do
Logging.with_logger(Logging.NullLogger()) do
# capture stderr, send stdout to devnull, don't skip loaded modules
Base.compilecache(pkg, sourcepath, iob, devnull, false)
# The false here means we ignore loaded modules, so precompile for a fresh session
Base.compilecache(pkg, sourcepath, std_pipe, std_pipe, false)
end
end
t_str = timing ? string(lpad(round(t * 1e3, digits = 1), 9), " ms") : ""
Expand All @@ -1472,11 +1472,11 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
end
loaded && (n_loaded += 1)
catch err
close(iob)
close(std_pipe.in) # close pipe to end the std output monitor
wait(t_monitor)
if err isa ErrorException || (err isa ArgumentError && startswith(err.msg, "Invalid header in cache file"))
failed_deps[pkg] = (strict || is_direct_dep) ? string(sprint(showerror, err), "\n", get(stderr_outputs, pkg, "")) : ""
delete!(stderr_outputs, pkg) # so it's not shown as warnings, given error report
failed_deps[pkg] = (strict || is_direct_dep) ? string(sprint(showerror, err), "\n", strip(get(std_outputs, pkg, ""))) : ""
delete!(std_outputs, pkg) # so it's not shown as warnings, given error report
!fancyprint && lock(print_lock) do
println(io, timing ? " "^9 : "", color_string(" ✗ ", Base.error_color()), name)
end
Expand All @@ -1486,6 +1486,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
rethrow()
end
finally
isopen(std_pipe.in) && close(std_pipe.in) # close pipe to end the std output monitor
wait(t_monitor)
Base.release(parallel_limiter)
end
else
Expand Down Expand Up @@ -1518,7 +1520,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
quick_exit = !all(istaskdone, tasks) || interrupted # if some not finished internal error is likely
seconds_elapsed = round(Int, (time_ns() - time_start) / 1e9)
ndeps = count(values(was_recompiled))
if ndeps > 0 || !isempty(failed_deps) || (quick_exit && !isempty(stderr_outputs))
if ndeps > 0 || !isempty(failed_deps) || (quick_exit && !isempty(std_outputs))
str = sprint() do iostr
if !quick_exit
plural = ndeps == 1 ? "y" : "ies"
Expand Down Expand Up @@ -1548,12 +1550,12 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
end
# show any stderr output, even if Pkg.precompile has been interrupted (quick_exit=true), given user may be
# interrupting a hanging precompile job with stderr output. julia#48371
filter!(kv -> !isempty(strip(last(kv))), stderr_outputs) # remove empty output
if !isempty(stderr_outputs)
plural1 = length(stderr_outputs) == 1 ? "y" : "ies"
plural2 = length(stderr_outputs) == 1 ? "" : "s"
print(iostr, "\n ", color_string("$(length(stderr_outputs))", Base.warn_color()), " dependenc$(plural1) had output during precompilation:")
for (pkgid, err) in stderr_outputs
filter!(kv -> !isempty(strip(last(kv))), std_outputs) # remove empty output
if !isempty(std_outputs)
plural1 = length(std_outputs) == 1 ? "y" : "ies"
plural2 = length(std_outputs) == 1 ? "" : "s"
print(iostr, "\n ", color_string("$(length(std_outputs))", Base.warn_color()), " dependenc$(plural1) had output during precompilation:")
for (pkgid, err) in std_outputs
err = join(split(strip(err), "\n"), color_string("\n│ ", Base.warn_color()))
print(iostr, color_string("\n┌ ", Base.warn_color()), pkgid, color_string("\n│ ", Base.warn_color()), err, color_string("\n└ ", Base.warn_color()))
end
Expand Down

0 comments on commit 0a4fb55

Please sign in to comment.