[BUG] julia-runtest shows wrong stack trace

[ulysses4ever]

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.

[SaschaMann]

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

[ulysses4ever]

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:

1. Fix the logger so that it doesn't eat the original stacktrace.
2. Document that stacktraces may be eaten if annotate: true is used.
3. Change the example in the documentation to not use annotate: true.

(A combination of these may work.)

[SaschaMann]

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?

[SaschaMann]

In the meantime, #77 adds a warning

[ericphanson]

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?

[ulysses4ever]

@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..

[ericphanson]

Ok, yeah, that looks like what I expect. Losing the stacktrace on nightly is concerning. I’ll try to look into it tomorrow.

[ericphanson]

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 (

julia-runtest/test_logger.jl

Lines 53 to 95 in 4867b26

	function build_stream(io)
	stream = Base.BufferStream()
	t = @async begin
	while !eof(stream)
	# Iterate through and print until we get to "Test Failed" and can parse it
	failed_line, _ = readlines_until(has_test_failure, stream; keep_lines=false, io)
	@label found_failed_line
	# Parse file and line out
	file, line_no = parse_file_line(failed_line)
	# Grab everything until the stacktrace, OR we hit another `Test Failed`
	stopped_line, msg_lines = readlines_until(stream; io) do line
	contains(line, "Stacktrace:") || has_test_failure(line)
	end
	# If we stopped because we hit a 2nd test failure,
	# let's assume somehow the stacktrace didn't show up for the first one.
	# Let's continue by trying to find the info for this one, by jumping back.
	if has_test_failure(stopped_line)
	failed_line = stopped_line
	@goto found_failed_line
	end
	if !isempty(msg_lines)
	msg = string("Test Failed\n", chomp(join(msg_lines)))
	# Now log it out
	@error msg _file=file _line=line_no
	end
	end
	end
	return stream, t
	end
	function test(args...; kwargs...)
	stream, t = build_stream(stdout)
	Base.errormonitor(t)
	return try
	Pkg.test(args...; kwargs..., io=stream)
	finally
	close(stream)
	end
	end

). 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, JuliaLang/Pkg.jl#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.

[ulysses4ever]

@ericphanson tremendous bug hunting!

[ericphanson]

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 JuliaLang/julia#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.

[ericphanson]

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.

[SaschaMann]

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

[ericphanson]

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 JuliaLang/Pkg.jl#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 JuliaLang/Pkg.jl#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).

[ericphanson]

filed JuliaLang/Pkg.jl#3430