Julia 1.11 beta MemoryRef bounds violation

[fonsp]

Pluto does not work on Julia 1.11 because of an error in our Pkg log capture system, but I can't figure out what it is. It seems to be caused by using a LoggingExtras.ConsoleLogger with an IOListener as its io argument.

When you launch a notebook, you get this error:

Instantiating...


Pkg error!

BoundsError: attempt to access MemoryRef{UInt8} at index [1]
Stacktrace:
  [1] GenericMemoryRef
    @ ./boot.jl:522 [inlined]
  [2] unsafe_copyto!
    @ ./genericmemory.jl:108 [inlined]
  [3] copyto!
    @ ./genericmemory.jl:143 [inlined]
  [4] _resize!(io::IOBuffer, sz::Int64)
    @ Base ./iobuffer.jl:309
  [5] ensureroom
    @ ./iobuffer.jl:391 [inlined]
  [6] unsafe_write(to::IOBuffer, p::Ptr{UInt8}, nb::UInt64)
    @ Base ./iobuffer.jl:508
  [7] unsafe_write
    @ ./io.jl:452 [inlined]
  [8] unsafe_write
    @ ./io.jl:803 [inlined]
  [9] write(s::IOContext{IOBuffer}, A::Vector{UInt8})
    @ Base ./io.jl:837
 [10] handle_message(logger::Logging.ConsoleLogger, level::Base.CoreLogging.LogLevel, message::Any, _module::Any, group::Any, id::Any, filepath::Any, line::Any; kwargs...)
    @ Logging /Applications/Julia-1.11.app/Contents/Resources/julia/share/julia/stdlib/v1.11/Logging/src/ConsoleLogger.jl:193
 [11] handle_message(::LoggingExtras.TeeLogger{Tuple{Logging.ConsoleLogger, Logging.ConsoleLogger}}, ::Base.CoreLogging.LogLevel, ::Vararg{Any}; kwargs::@Kwargs{exception::BoundsError})
    @ LoggingExtras ~/.julia/packages/LoggingExtras/VLO3o/src/CompositionalLoggers/tee.jl:24
 [12] invokelatest(::Any, ::Any, ::Vararg{Any}; kwargs::@Kwargs{exception::BoundsError})
    @ Base ./essentials.jl:1032
 [13] macro expansion
    @ ./logging.jl:376 [inlined]
 [14] with_auto_fixes(f::Pluto.var"#133#150"{Pluto.Notebook, Pluto.IOListener}, notebook::Pluto.Notebook)
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:485
 [15] #132
    @ ~/Documents/Pluto.jl/src/packages/Packages.jl:180 [inlined]
 [16] report_business!(f::Pluto.var"#132#149"{Pluto.Notebook, Pluto.IOListener}, parent::Pluto.Status.Business, args::Symbol)
    @ Pluto.Status ~/Documents/Pluto.jl/src/webserver/Status.jl:82
 [17] (::Pluto.var"#131#148"{Pluto.Configuration.CompilerOptions, Pluto.Notebook, Nothing, Pluto.IOListener, Vector{String}, Vector{String}, Bool, Bool, Pluto.Status.Business})()
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:179
 [18] with_logstate(f::Pluto.var"#131#148"{Pluto.Configuration.CompilerOptions, Pluto.Notebook, Nothing, Pluto.IOListener, Vector{String}, Vector{String}, Bool, Bool, Pluto.Status.Business}, logstate::Base.CoreLogging.LogState)
    @ Base.CoreLogging ./logging.jl:522
 [19] with_logger(f::Function, logger::LoggingExtras.TeeLogger{Tuple{Logging.ConsoleLogger, Logging.ConsoleLogger}})
    @ Base.CoreLogging ./logging.jl:632
 [20] withlogcapture(f::Function, iolistener::Pluto.IOListener)
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:719
 [21] #130
    @ ~/Documents/Pluto.jl/src/packages/Packages.jl:143 [inlined]
 [22] withtoken(f::Pluto.var"#130#147"{Pluto.Configuration.CompilerOptions, Pluto.Notebook, Nothing, Pluto.IOListener, Vector{String}, Vector{String}, Bool, Bool, Pluto.Status.Business}, token::Pluto.Token)
    @ Pluto ~/Documents/Pluto.jl/src/evaluation/Tokens.jl:19
 [23] sync_nbpkg_core(notebook::Pluto.Notebook, old_topology::PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}, new_topology::PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}; on_terminal_output::Pluto.var"#iocallback#168"{Pluto.ServerSession, Pluto.Notebook}, cleanup::Base.RefValue{Function}, lag::Float64, compiler_options::Pluto.Configuration.CompilerOptions)
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:142
 [24] (::Pluto.var"#165#167"{Pluto.ServerSession, Pluto.Notebook, PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}, PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}, Base.RefValue{Function}})()
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:342
 [25] sync_nbpkg(session::Pluto.ServerSession, notebook::Pluto.Notebook, old_topology::PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}, new_topology::PlutoDependencyExplorer.NotebookTopology{Pluto.Cell}; save::Bool, take_token::Bool)
    @ Pluto ~/Documents/Pluto.jl/src/packages/Packages.jl:328
 [26] (::Pluto.var"#236#242"{Bool, @Kwargs{}, Pluto.ServerSession, Pluto.Notebook})()
    @ Pluto ~/Documents/Pluto.jl/src/evaluation/Run.jl:466
 [27] withtoken(f::Pluto.var"#236#242"{Bool, @Kwargs{}, Pluto.ServerSession, Pluto.Notebook}, token::Pluto.Token)
    @ Pluto ~/Documents/Pluto.jl/src/evaluation/Tokens.jl:19
 [28] #235
    @ ~/Documents/Pluto.jl/src/evaluation/Run.jl:450 [inlined]
 [29] (::Pluto.var"#227#228"{Pluto.var"#235#241"{Bool, @Kwargs{}, Pluto.ServerSession, Pluto.Notebook}})()
    @ Pluto ~/Documents/Pluto.jl/src/evaluation/Tokens.jl:58
Evaluating cells (3/3)

(pkg> test Pluto will also show them)

The stacktrace points to this @info call, which is handled by this logger.

We read the contents of the IOBuffer async here, maybe this is causing a race condition?

I tried to recreate this bug with this script:

import Pluto
listener = Pluto.IOListener(callback=(args...)->nothing)
    
Pluto.withlogcapture(listener) do
    try
        sqrt(-1)
    catch e
        @info "huh" exception=e
    end
end

But this did not cause the error...

[vtjnash]

It looks like you wanted to use a Base.BufferStream there, but implemented a buggy version of it as IOListener?

[fonsp]

Thanks for taking a look @vtjnash, so you do think that the async reading from the IOBuffer is causing the issue?

Will I get in trouble for using internal API? Maybe https://github.com/JuliaPackaging/SimpleBufferStream.jl is a good option?

[vtjnash]

I am uncertain of the quality of that package, so I cannot recommend for or against it. The documentation seems lacking though. BufferStream has been meant to be public for a long while though, if that is any consolation