julia-runtest
julia-runtest copied to clipboard
julia-actions
[BUG] julia-runtest shows wrong stack trace
Describe the bug Consider the following failed workflow run:
Testing Running tests...
ERROR: LoadError: Some tests did not pass: 1 passed, 0 failed, 1 errored, 0 broken.
in expression starting at /home/runner/work/julia-type-stability/julia-type-stability/Stability/test/runtests.jl:10
ERROR: LoadError: Package Stability errored during testing
Stacktrace:
[1] pkgerror(msg::String)
@ Pkg.Types /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/Types.jl:69
[2] test(ctx::Pkg.Types.Context, pkgs::Vector{Pkg.Types.PackageSpec}; coverage::Bool, julia_args::Cmd, test_args::Cmd, test_fn::Nothing, force_latest_compatible_version::Bool, allow_earlier_backwards_compatible_versions::Bool, allow_reresolve::Bool)
@ Pkg.Operations /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/Operations.jl:2012
[3] test
@ /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/Operations.jl:1893 [inlined]
[4] test(ctx::Pkg.Types.Context, pkgs::Vector{Pkg.Types.PackageSpec}; coverage::Bool, test_fn::Nothing, julia_args::Vector{String}, test_args::Cmd, force_latest_compatible_version::Bool, allow_earlier_backwards_compatible_versions::Bool, allow_reresolve::Bool, kwargs::Base.Pairs{Symbol, Base.BufferStream, Tuple{Symbol}, NamedTuple{(:io,), Tuple{Base.BufferStream}}})
@ Pkg.API /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/API.jl:441
[5] test(pkgs::Vector{Pkg.Types.PackageSpec}; io::Base.BufferStream, kwargs::Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:coverage, :julia_args, :force_latest_compatible_version), Tuple{Bool, Vector{String}, Bool}}})
@ Pkg.API /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/API.jl:156
[6] test
@ /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/API.jl:145 [inlined]
[7] test(; name::Nothing, uuid::Nothing, version::Nothing, url::Nothing, rev::Nothing, path::Nothing, mode::Pkg.Types.PackageMode, subdir::Nothing, kwargs::Base.Pairs{Symbol, Any, NTuple{4, Symbol}, NamedTuple{(:coverage, :julia_args, :force_latest_compatible_version, :io), Tuple{Bool, Vector{String}, Bool, Base.BufferStream}}})
@ Pkg.API /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/API.jl:171
[8] test
@ /opt/hostedtoolcache/julia/nightly/x64/share/julia/stdlib/v1.10/Pkg/src/API.jl:162 [inlined]
[9] test(; kwargs::Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:coverage, :julia_args, :force_latest_compatible_version), Tuple{Bool, Vector{String}, Bool}}})
@ Main.TestLogger ~/work/_actions/julia-actions/julia-runtest/v1/test_logger.jl:91
[10] top-level scope
@ ~/work/_actions/julia-actions/julia-runtest/v1/test_harness.jl:13
[11] include(fname::String)
@ Base.MainInclude ./client.jl:478
[12] top-level scope
@ none:1
in expression starting at /home/runner/work/_actions/julia-actions/julia-runtest/v1/test_harness.jl:7
Error: Process completed with exit code 1.
This stacktrace is mostly irrelevant. The only relevant bit is runtests.jl:10, which is a toplevel @testset call which is not super helpful.
Now, what I see locally when I run Pkg.test manually is:
Testing Running tests...
Basic tests for computing module stats: Error During Test at /data/artem/stability/repo/Stability/test/runtests.jl:10
Got exception outside of a @test
MethodError: no method matching getindex(::Core.MethodInstance, ::Int64)
Stacktrace:
[1] macro expansion
@ /data/artem/stability/repo/Stability/test/runtests.jl:19 [inlined]
[2] macro expansion
@ ~/Dev/julia/julia-6d678fec0a/share/julia/stdlib/v1.10/Test/src/Test.jl:1504 [inlined]
[3] top-level scope
@ /data/artem/stability/repo/Stability/test/runtests.jl:14
[4] include(fname::String)
@ Base.MainInclude ./client.jl:478
[5] top-level scope
@ none:6
[6] eval
@ ./boot.jl:370 [inlined]
[7] exec_options(opts::Base.JLOptions)
@ Base ./client.jl:280
[8] _start()
@ Base ./client.jl:541
Test Summary: | Pass Error Total Time
Basic tests for computing module stats | 1 1 2 3.1s
ERROR: LoadError: Some tests did not pass: 1 passed, 0 failed, 1 errored, 0 broken.
in expression starting at /data/artem/stability/repo/Stability/test/runtests.jl:10
ERROR: Package Stability errored during testing
Not only it doesn't have a lot of garbage in the stack trace, but it also mentions exactly the line where I have a problem: runtests.jl:19.
So, what does the action do differently, and is it possible to have the relevant stacktrace in the CI?
To Reproduce Checkout prl-julia/julia-type-stability@464b43f and run its tests with a (reasonably recent) nightly Julia.
Expected behavior Show the stacktrace that I see locally.
Could you remove the annotate input for testing?
So, what does the action do differently
If annotations are enabled, it wraps the Pkg.test call in a custom logger: https://github.com/julia-actions/julia-runtest/blob/main/test_harness.jl
I see, thanks a lot for the explanation. Indeed, annotation: false fixes it (here's the run) in the sense that the original stacktrace is preserved now (the useless one is still there, though).
I wasn't sure if I need annotation: true, but I got it from the documentation example. Perhaps, this is not a great default to put into example... (I assume, many people will copy-paste it without thinking much and can be bitten like I was).
So, this is a kind of a workaround that works for me, and I don't mind closing it. But I think something needs to be done. Options:
- Fix the logger so that it doesn't eat the original stacktrace.
- Document that stacktraces may be eaten if
annotate: trueis used. - Change the example in the documentation to not use
annotate: true.
(A combination of these may work.)
Perhaps, this is not a great default to put into example...
Agreed. It's not enabled by default for a reason.
But I think something needs to be done.
Yeah but I'm not sure how to fix it properly. I assume the stacktrace will always include parts from the test harness.
@ericphanson any idea?
It definitely should be fixable! I am not sure what changed but I’m 99% sure it wasn’t doing this before 🤔. Do you see that on 1.8 also @ulysses4ever or only on nightly?
@ericphanson indeed, on 1.8 I see both stacktraces (e.g. this run), which is good. Nightly somehow broke this, and I only see the useless one..
Ok, yeah, that looks like what I expect. Losing the stacktrace on nightly is concerning. I’ll try to look into it tomorrow.
Ok, more like 2 weeks than "tomorrow", but let's see. (Here I wrote out most of my debugging as I went, to help me keep track of what was going on - jump to the end for the conclusion).
I cloned Example.jl, added a @test false to the tests, then tried it out on 1.9-beta4:
julia> include("../julia-runtest/test_logger.jl")
Main.TestLogger
julia> TestLogger.test()
Testing Example
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_4eE5eh/Project.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[8dfed614] Test `@stdlib/Test`
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_4eE5eh/Manifest.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[2a0f44e3] Base64 `@stdlib/Base64`
[b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
[56ddb016] Logging `@stdlib/Logging`
[d6f4376e] Markdown `@stdlib/Markdown`
[9a3f8284] Random `@stdlib/Random`
[ea8e919c] SHA v0.7.0 `@stdlib/SHA`
[9e88b42a] Serialization `@stdlib/Serialization`
[8dfed614] Test `@stdlib/Test`
Testing Running tests...
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
Stacktrace:
[1] pkgerror(msg::String)
@ Pkg.Types ~/.julia/juliaup/julia-1.9.0-beta4+0.aarch64.apple.darwin14/share/julia/stdlib/v1.9/Pkg/src/Types.jl:68
...omitted...
whereas on 1.8.5, I get:
julia> include("../julia-runtest/test_logger.jl")
Main.TestLogger
julia> TestLogger.test()
Testing Example
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_nBwAjB/Project.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[8dfed614] Test `@stdlib/Test`
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_nBwAjB/Manifest.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[2a0f44e3] Base64 `@stdlib/Base64`
[b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
[56ddb016] Logging `@stdlib/Logging`
[d6f4376e] Markdown `@stdlib/Markdown`
[9a3f8284] Random `@stdlib/Random`
[ea8e919c] SHA v0.7.0 `@stdlib/SHA`
[9e88b42a] Serialization `@stdlib/Serialization`
[8dfed614] Test `@stdlib/Test`
Precompiling project...
✓ Example
1 dependency successfully precompiled in 0 seconds
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
┌ Error: Test Failed
│ Expression: false
└ @ Main.TestLogger ~/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
Stacktrace:
[1] pkgerror(msg::String)
@ Pkg.Types ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/Types.jl:67
...omitted...
So indeed I can reproduce the regression, which is the lack of printing
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
in the 1.9 run, which is printed on 1.8, along with the lack of the logging output,
┌ Error: Test Failed
│ Expression: false
└ @ Main.TestLogger ~/Example.jl/test/runtests.jl:5
which is used to power the annotations that are supposed to show up.
In both cases, Pkg.test() gives me the same output:
julia> using Pkg
julia> Pkg.test()
Testing Example
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_y7Sa6L/Project.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[8dfed614] Test `@stdlib/Test`
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_y7Sa6L/Manifest.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[2a0f44e3] Base64 `@stdlib/Base64`
[b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
[56ddb016] Logging `@stdlib/Logging`
[d6f4376e] Markdown `@stdlib/Markdown`
[9a3f8284] Random `@stdlib/Random`
[ea8e919c] SHA v0.7.0 `@stdlib/SHA`
[9e88b42a] Serialization `@stdlib/Serialization`
[8dfed614] Test `@stdlib/Test`
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
Stacktrace:
[1] pkgerror(msg::String)
@ Pkg.Types ~/.julia/juliaup/julia-1.9.0-beta4+0.aarch64.apple.darwin14/share/julia/stdlib/v1.9/Pkg/src/Types.jl:68
...omitted...
and if I pass the key part into our tests on this repo, on 1.9,
output, logs = simulate("""
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
""")
I do see that we parse it out OK:
julia> logs[1]
LogRecord(Error, "Test Failed\n Expression: false\nERROR: LoadError: There was an error during testing\nin expression starting at /Users/eph/Example.jl/test/runtests.jl:5\nERROR: Package Example errored during testing", Main.TestLogger, :file, :Main_TestLogger_73f824aa, "/Users/eph/Example.jl/test/runtests.jl", "5", Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}())
and the output looks right:
julia> println(output)
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
Ok, so where does that leave us?
- Clear regression from Julia 1.8.5 to 1.9
- Pkg printing hasn't changed
- if we read the input correctly, then we still do the right thing (as shown by
simulate)
So what is left? I think it must be the code that is supposed to read the output of Pkg.test and pass it along is not working right (https://github.com/julia-actions/julia-runtest/blob/4867b265f331ce2e0adab325b9dc55efeaf853d3/test_logger.jl#L53-L95). I think that either could be Pkg isn't using the io argument the same way, or something in the BufferStream or other code isn't working the way I expect.
Ok, moving forward, on both 1.8.5 and 1.9 I get essentially the same results if I do:
julia> io = Base.BufferStream()
BufferStream(bytes waiting=0, isopen=true)
julia> Pkg.test(; io);
ERROR: LoadError: There was an error during testing
in expression starting at /Users/eph/Example.jl/test/runtests.jl:5
ERROR: Package Example errored during testing
Stacktrace:
[1] pkgerror(msg::String)
@ Pkg.Types ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/Types.jl:67
[2] test(ctx::Pkg.Types.Context, pkgs::Vector{Pkg.Types.PackageSpec}; coverage::Bool, julia_args::Cmd, test_args::Cmd, test_fn::Nothing, force_latest_compatible_version::Bool, allow_earlier_backwards_compatible_versions::Bool, allow_reresolve::Bool)
@ Pkg.Operations ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/Operations.jl:1813
[3] test(ctx::Pkg.Types.Context, pkgs::Vector{Pkg.Types.PackageSpec}; coverage::Bool, test_fn::Nothing, julia_args::Cmd, test_args::Cmd, force_latest_compatible_version::Bool, allow_earlier_backwards_compatible_versions::Bool, allow_reresolve::Bool, kwargs::Base.Pairs{Symbol, Base.BufferStream, Tuple{Symbol}, NamedTuple{(:io,), Tuple{Base.BufferStream}}})
@ Pkg.API ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/API.jl:434
[4] test(pkgs::Vector{Pkg.Types.PackageSpec}; io::Base.BufferStream, kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
@ Pkg.API ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/API.jl:156
[5] test(; name::Nothing, uuid::Nothing, version::Nothing, url::Nothing, rev::Nothing, path::Nothing, mode::Pkg.Types.PackageMode, subdir::Nothing, kwargs::Base.Pairs{Symbol, Base.BufferStream, Tuple{Symbol}, NamedTuple{(:io,), Tuple{Base.BufferStream}}})
@ Pkg.API ~/.julia/juliaup/julia-1.8.5+0.aarch64.apple.darwin14/share/julia/stdlib/v1.8/Pkg/src/API.jl:0
[6] top-level scope
@ REPL[14]:1
julia> println(read(io, String))
Testing Example
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_JTxFAY/Project.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[8dfed614] Test `@stdlib/Test`
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_JTxFAY/Manifest.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[2a0f44e3] Base64 `@stdlib/Base64`
[b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
[56ddb016] Logging `@stdlib/Logging`
[d6f4376e] Markdown `@stdlib/Markdown`
[9a3f8284] Random `@stdlib/Random`
[ea8e919c] SHA v0.7.0 `@stdlib/SHA`
[9e88b42a] Serialization `@stdlib/Serialization`
[8dfed614] Test `@stdlib/Test`
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
which tells me that Pkg is still handling the io argument correctly and passing the info to the BufferStream.
And indeed, if I do that again, but pass the string to simulate instead of printing it, our parsing code is still able to work correctly:
julia> output, logs = simulate(" Testing Example\n Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_SwEA3z/Project.toml`\n [7876af07] Example v0.5.4 `~/Example.jl`\n [8dfed614] Test `@stdlib/Test`\n Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_SwEA3z/Manifest.toml`\n [7876af07] Example v0.5.4 `~/Example.jl`\n [2a0f44e3] Base64 `@stdlib/Base64`\n [b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`\n [56ddb016] Logging `@stdlib/Logging`\n [d6f4376e] Markdown `@stdlib/Markdown`\n [9a3f8284] Random `@stdlib/Random`\n [ea8e919c] SHA v0.7.0 `@stdlib/SHA`\n [9e88b42a] Serialization `@stdlib/Serialization`\n [8dfed614] Test `@stdlib/Test`\n Testing Running tests...\n\e[91m\e[1mTest Failed\e[22m\e[39m at \e[39m\e[1m/Users/eph/Example.jl/test/runtests.jl:5\e[22m\n Expression: false\n");
julia> println(output)
Testing Example
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_SwEA3z/Project.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[8dfed614] Test `@stdlib/Test`
Status `/private/var/folders/jb/plyyfc_d2bz195_0rc0n_zcw0000gp/T/jl_SwEA3z/Manifest.toml`
[7876af07] Example v0.5.4 `~/Example.jl`
[2a0f44e3] Base64 `@stdlib/Base64`
[b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
[56ddb016] Logging `@stdlib/Logging`
[d6f4376e] Markdown `@stdlib/Markdown`
[9a3f8284] Random `@stdlib/Random`
[ea8e919c] SHA v0.7.0 `@stdlib/SHA`
[9e88b42a] Serialization `@stdlib/Serialization`
[8dfed614] Test `@stdlib/Test`
Testing Running tests...
Test Failed at /Users/eph/Example.jl/test/runtests.jl:5
Expression: false
julia> logs[1]
LogRecord(Error, "Test Failed\n Expression: false", Main.TestLogger, :file, :Main_TestLogger_73f824aa, "/Users/eph/Example.jl/test/runtests.jl", "5", Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}())
Ok, so something else is wrong. Adding some print statements into each branch of my readlines_until function shows that on 1.9 we are hitting the == "" branch before we are hitting the if f branch, but not on 1.8. If I change == "" to eof(stream) I seem to get the same results, i.e. eof is somehow returning true too early?
I am a bit out of my depth w/r/t/ how streams work (clearly, if you look at some of the comments in that file 😅), so I turned to bisecting julia between 1.8.5 and 1.9-beta4 . I haven't done that before but it seemed like a good opportunity to learn.
I opened my clone of julia and ran:
❯ git bisect start v1.9.0-beta4 v1.8.5
HEAD is now at 17cfb8e65e set VERSION to 1.8.5 (#48132)
Bisecting: a merge base must be tested
[7a1c20e6dea50291b364452996d3d4d71a6133dc] Eagerly do boundscheck when indexing CartesianIndices with CartesianIndices (#42235)
❯ git bisect run ../my_bisection_script.jl
where the contents of the script (after some iteration) are here:
`my_bisection_script.jl`
#!/usr/bin/env -S julia --color=yes --startup-file=no
println("Building...")
@time try
run(pipeline(`make -j4`; stdout=devnull, stderr=devnull))
catch
println("Error when building. Trying `make cleanall`...")
try
run(pipeline(`make cleanall`; stdout=devnull, stderr=devnull))
println("Trying again to build...")
run(pipeline(`make -j4`; stdout=devnull, stderr=devnull))
catch
println("Still couldn't build...")
run(`git status`)
exit(125)
end
end
println("Testing...")
@time begin
script = """
cd(expanduser("~/Example.jl"))
include("../julia-runtest/test_logger.jl")
using Pkg
Pkg.activate(".")
try
TestLogger.test()
catch
end
"""
out = IOBuffer()
err = IOBuffer()
run(pipeline(`./julia --startup-file=no -e $script`, stdout=out, stderr=err))
end
println("Checking results...")
if contains(String(take!(out)), "Expression: false")
println("Commit good!")
exit(0)
else
println("Commit bad!")
exit(1)
end
After an hour or so, that gave me:
14d3cafe44aceb194b8fadd36091a8814b6b14aa is the first bad commit
commit 14d3cafe44aceb194b8fadd36091a8814b6b14aa
Author: Kristoffer <[email protected]>
Date: Mon Jan 2 15:50:02 2023 +0100
update Pkg
deps/checksums/Pkg-5d8b9ddb89ef7eff7c4d032cd4a7e33778c0bbde.tar.gz/md5 | 1 -
.../Pkg-5d8b9ddb89ef7eff7c4d032cd4a7e33778c0bbde.tar.gz/sha512 | 1 -
deps/checksums/Pkg-936a3f9e4c1b5865212ff0174774fe7af454862c.tar.gz/md5 | 1 +
.../Pkg-936a3f9e4c1b5865212ff0174774fe7af454862c.tar.gz/sha512 | 1 +
stdlib/Pkg.version | 2 +-
5 files changed, 3 insertions(+), 3 deletions(-)
delete mode 100644 deps/checksums/Pkg-5d8b9ddb89ef7eff7c4d032cd4a7e33778c0bbde.tar.gz/md5
delete mode 100644 deps/checksums/Pkg-5d8b9ddb89ef7eff7c4d032cd4a7e33778c0bbde.tar.gz/sha512
create mode 100644 deps/checksums/Pkg-936a3f9e4c1b5865212ff0174774fe7af454862c.tar.gz/md5
create mode 100644 deps/checksums/Pkg-936a3f9e4c1b5865212ff0174774fe7af454862c.tar.gz/sha512
which is this commit, and corresponds to these changes in Pkg.jl. Of those changes, https://github.com/JuliaLang/Pkg.jl/pull/3281 looks the most related to me.
And indeed, I think we are somehow stopping after precompilation, because if I add a println("hi") to the start of Example.jl's tests, I don't see it when doing TestLogger.test().
Looking up what eof means, wikipedia tells me you can have more than one EOF in a stream, since you might send more than 1 file down the stream. Makes sense to me, so exiting when we hit the first EOF as I do here is incorrect. Instead, I can check if the stream is still iswritable, since after we close it in the finally block, it won't be anymore, and thus make sure we don't exit early. I can also remove some of the other checks that cause us to exit early. This @async task won't cause Julia to stay running, so it doesn't really matter if it exits nicely or not, as long as we flush it out, which the close in the finally block will do.
I will put up a PR to make these changes and add a more comprehensive test.
Hm, my “fix” isn’t holding up to more robust testing. I think it’s kinda hard if we can’t rely on “eof” to mean there’s nothing left; for example, the stream could be closed & done, but we aren’t so far along, and we hit an earlier eof rather than the last one.
Even tee from https://github.com/JuliaLang/julia/issues/47200 doesn’t help in that case.
So I am feeling a bit stuck. I think the best thing would be something like that tee but (maybe with a while true instead of looking for eof) to decouple things, by copying over all bytes as they come to a secondary stream, and then try to parse the failures out of that stream to make the GitHub annotations while letting the normal text go to stdout, instead of trying to parse failures to log them while printing lines to stdout. I need to refactor my parsing code though I think.
In the meantime think maybe we should turn off annotations (even if it is selected by the user) on Julia 1.9-beta3 onwards, by adding another version check, since this is a pretty big issue. Hopefully we can figure out how to restore the functionality as well though.
Great bug hunting! :)
Hopefully we can figure out how to restore the functionality as well though.
I'm way out of my depth on streams. I'll try to look into it more closely at some point but perhaps someone on Slack/Zulip could help out
I did a bit more reading (I'm very much out of my depth on streams too), and it seems EOF isn't a token or marker placed into the stream like I had kinda thought (like a newline) but rather a property of the stream itself. But I think we are in a weird limbo with Base.BufferStream where the stream can have eof(stream) return true, but then start to produce more values. For example:
julia> io = Base.BufferStream()
BufferStream(bytes waiting=0, isopen=true)
julia> let
t = @async begin
for _ = 1:100
bytes = readavailable(io)
@show String(bytes)
@show eof(io)
end
end
run(pipeline(`echo "hi"`, stdout=io))
run(pipeline(`echo "bye"`, stdout=io))
end
String(bytes) = "hi\n"
eof(io) = true
String(bytes) = ""
eof(io) = true
String(bytes) = ""
eof(io) = true
String(bytes) = "bye\n"
eof(io) = true
String(bytes) = ""
eof(io) = true
...
But if you use Base.PipeBuffer instead, you get an error and only the first "file" coming through:
julia> io = Base.PipeBuffer()
IOBuffer(data=UInt8[...], readable=true, writable=true, seekable=false, append=true, size=0, maxsize=Inf, ptr=1, mark=-1)
julia> let
t = @async begin
for _ = 1:100
bytes = readavailable(io)
@show String(bytes)
@show eof(io)
end
end
run(pipeline(`echo "hi"`, stdout=io))
run(pipeline(`echo "bye"`, stdout=io))
end
String(bytes) = ""
eof(io) = false┌ Warning: Process I/O error
│ exception =
│ ArgumentError: ensureroom failed, IOBuffer is not writeable
│ Stacktrace:
│ [1] ensureroom_slowpath(io::IOBuffer, nshort::UInt64)
│ @ Base ./iobuffer.jl:303
│ [2] ensureroom
│ @ ./iobuffer.jl:325 [inlined]
│ [3] unsafe_write(to::IOBuffer, p::Ptr{UInt8}, nb::UInt64)
│ @ Base ./iobuffer.jl:424
│ [4] unsafe_write
│ @ ./io.jl:685 [inlined]
│ [5] write
│ @ ./io.jl:708 [inlined]
│ [6] write(to::IOBuffer, from::Base.PipeEndpoint)
│ @ Base ./io.jl:755
│ [7] macro expansion
│ @ ./process.jl:300 [inlined]
│ [8] (::Base.var"#764#765"{IOBuffer, Bool, Base.PipeEndpoint, IOBuffer, Base.PipeEndpoint})()
│ @ Base ./task.jl:514
└ @ Base process.jl:302
String(bytes) = "hi\n"
eof(io) = true
String(bytes) = ""
eof(io) = true
String(bytes) = ""
eof(io) = true
...
which kind of makes more sense to me.
Note: running two external commands with the same stdout is exactly what https://github.com/JuliaLang/Pkg.jl/pull/3281 does which causes this regression here, which is why I'm using it for my examples.
So I think one perspective is that you aren't supposed to use the same io for stdout for two commands, and https://github.com/JuliaLang/Pkg.jl/pull/3281 is thus buggy. But it works for stdout, so maybe there is some kind of IO type it is supposed to work with?
So one possibility is that Base.BufferStream producing more values after it says eof is some kind of weird bug, and that PR shouldn't be re-using IO objects (so it's a Pkg.jl bug, in this scenario). Another possibility is there is some restricted class of IO objects that you are allowed to do this, and the fix then is to figure out what those are and how to use them, to recover the functionality here (and Pkg.jl is possibly just missing some docs on what the io argument is allowed to be, but isn't buggy).