Test suite fails with `Base_Docs_4352b6d8` error (again)

[t-bltg]

LoadError: UndefVarError: Base_Docs_4352b6d8 not defined appears again.

Not only locally when developing, but also in CI (e.g. https://github.com/timholy/Revise.jl/runs/7479727981?check_suite_focus=true).

Base signatures: Error During Test at /home/runner/work/Revise.jl/Revise.jl/test/runtests.jl:4061
  Got exception outside of a @test
  LoadError: UndefVarError: Base_Docs_4352b6d8 not defined
  Stacktrace:
    [1] collect_args(recurse::Any, frame::Frame, call_expr::Expr; isfc::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:60
    [2] collect_args
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:136 [inlined]
    [3] evaluate_call_recurse!(recurse::Any, frame::Frame, call_expr::Expr; enter_generated::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:233
    [4] evaluate_call_recurse!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:227 [inlined]
    [5] eval_rhs(recurse::Any, frame::Frame, node::Expr)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:399
    [6] step_expr!(recurse::Any, frame::Frame, node::Any, istoplevel::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:552
    [7] step_expr!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:602 [inlined]
    [8] finish!(recurse::Any, frame::Frame, istoplevel::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/commands.jl:14
    [9] finish_and_return!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/commands.jl:30 [inlined]
   [10] evaluate_call_recurse!(recurse::Any, frame::Frame, call_expr::Expr; enter_generated::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:266
   [11] evaluate_call_recurse!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:227 [inlined]
   [12] eval_rhs(recurse::Any, frame::Frame, node::Expr)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:399
   [13] step_expr!(recurse::Any, frame::Frame, node::Any, istoplevel::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:552
   [14] step_expr!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:602 [inlined]
   [15] finish!(recurse::Any, frame::Frame, istoplevel::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/commands.jl:14
   [16] finish_and_return!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/commands.jl:30 [inlined]
   [17] evaluate_call_recurse!(recurse::Any, frame::Frame, call_expr::Expr; enter_generated::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:266
   [18] evaluate_call_recurse!
    @ ~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:227 [inlined]
   [19] eval_rhs(recurse::Any, frame::Frame, node::Expr)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:399
   [20] step_expr!(recurse::Any, frame::Frame, node::Any, istoplevel::Bool)
    @ JuliaInterpreter~/.julia/packages/JuliaInterpreter/Q7nmG/src/interpret.jl:547
   [21] signature(recurse::Any, frame::Frame, stmt::Any, pc::Int64)
    @ LoweredCodeUtils~/.julia/packages/LoweredCodeUtils/0oUEK/src/signatures.jl:51
   [22] methoddef!(recurse::Any, signatures::Vector{Any}, frame::Frame, stmt::Any, pc::Int64; define::Bool)
    @ LoweredCodeUtils~/.julia/packages/LoweredCodeUtils/0oUEK/src/signatures.jl:493
   [23] methods_by_execution!(recurse::Any, methodinfo::Revise.CodeTrackingMethodInfo, docexprs::Dict{Module, Vector{Expr}}, frame::Frame, isrequired::Vector{Bool}; mode::Symbol, skip_include::Bool)
    @ Revise~/work/Revise.jl/Revise.jl/src/lowered.jl:272
   [24] methods_by_execution!(recurse::Any, methodinfo::Revise.CodeTrackingMethodInfo, docexprs::Dict{Module, Vector{Expr}}, mod::Module, ex::Expr; mode::Symbol, disablebp::Bool, always_rethrow::Bool, kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Revise~/work/Revise.jl/Revise.jl/src/lowered.jl:217
   [25] #eval_with_signatures#90
    @ ~/work/Revise.jl/Revise.jl/src/packagedef.jl:464 [inlined]
   [26] instantiate_sigs!(modexsigs::OrderedCollections.OrderedDict{Module, OrderedCollections.OrderedDict{Revise.RelocatableExpr, Union{Nothing, Vector{Any}}}}; mode::Symbol, kwargs::Base.Pairs{Symbol, Bool, Tuple{Symbol}, NamedTuple{(:always_rethrow,), Tuple{Bool}}})
    @ Revise~/work/Revise.jl/Revise.jl/src/packagedef.jl:472
   [27] macro expansion
    @ ~/work/Revise.jl/Revise.jl/test/sigtest.jl:102 [inlined]
   [28] top-level scope
    @ ./timing.jl:220
   [29] include(fname::String)
    @ Base.MainInclude/opt/hostedtoolcache/julia/1.7.3/x64/share/julia/base/client.jl:451
   [30] macro expansion
    @ ~/work/Revise.jl/Revise.jl/test/runtests.jl:4064 [inlined]
   [31] macro expansion
    @ /opt/hostedtoolcache/julia/1.7.3/x64/share/julia/stdlib/v1.7/Test/src/Test.jl:1283 [inlined]
   [32] top-level scope
    @ ~/work/Revise.jl/Revise.jl/test/runtests.jl:4062
   [33] include(fname::String)
    @ Base.MainInclude/opt/hostedtoolcache/julia/1.7.3/x64/share/julia/base/client.jl:451
   [34] top-level scope
    @ none:6
   [35] eval
    @ ./boot.jl:373 [inlined]
   [36] exec_options(opts::Base.JLOptions)
    @ Base/opt/hostedtoolcache/julia/1.7.3/x64/share/julia/base/client.jl:268
   [37] _start()
    @ Base/opt/hostedtoolcache/julia/1.7.3/x64/share/julia/base/client.jl:495
  in expression starting at /home/runner/work/Revise.jl/Revise.jl/test/sigtest.jl:97

This is very frustrating, because it affects local development, PRs workflow, and IMO should be treated as top priority.
I'm trying to fix this now.

Reproduce locally (on 1.7.3) with:

$  cd /tmp; git clone https://github.com/timholy/Revise.jl
$ julia
] dev /tmp/Revise.jl
] test Revise

Xref:
JuliaDebug/JuliaInterpreter.jl#423
#505
#520
#561
JuliaDebug/JuliaInterpreter.jl#441
JuliaDebug/JuliaInterpreter.jl#440
JuliaDebug/JuliaInterpreter.jl#444
JuliaDebug/JuliaInterpreter.jl#442
JuliaDebug/JuliaInterpreter.jl#535

[t-bltg]

Culprit from Pkg/ext/LazilyInitializedFields/LazilyInitializedFields.jl:

stmt = :($(Expr(:method, nothing, %J50, CodeInfo(
    @ /usr/share/julia/stdlib/v1.7/Pkg/ext/LazilyInitializedFields/LazilyInitializedFields.jl:74 within `none`
1 ─ %1 = print(io, "uninit")
└──      return %1
))))

[timholy]

Yeah, it's a JuliaInterpreter bug. Something changed its quoting in a recent Julia release, and I haven't had time to chase down the right fix. It's being accessed from here but the right fix must be earlier in JuliaInterpreter's handling of that expression.

[t-bltg]

Thanks for the comment and hints. Deep down the code now, I'm onto it 😆

Involving Docs, Logging, Pkg/ext/LazilyInitializedFields/LazilyInitializedFields.jl:

call_expr = :(($(QuoteNode(Base.CoreLogging._invoked_shouldlog)))(_J13, _J17, _J14, _J15, _J12))
fargs = Any[Base.CoreLogging._invoked_shouldlog, Logging.ConsoleLogger(IOBuffer(data=UInt8[...], readable=false, writable=false, seekable=false, append=false, size=0, maxsize=0, ptr=1, mark=-1), Info, Logging.default_metafmt, true, 0, Dict{Any, Int64}()), Warn, Base.Docs, :Docs, :Base_Docs_4352b6d8]
frame = Frame for doc!(__module__::Module, b::Base.Docs.Binding, str::Base.Docs.DocStr, sig) in Base.Docs at [...]/base/docs/Docs.jl:226
   1  228  1 ──       nothing
   2  228  │          __module__@_19 = __module__@_2
   3  228  │          Core.NewvarNode(:(m))
   4  228  │          Core.NewvarNode(:(obj))
   5  228  │    %5  = Base.Docs.defined(b)
   6  228  └───       goto #4 if not %5
   7  229  2 ──       obj = Base.Docs.resolve(b)
   8  230  │    %8  = obj isa $(QuoteNode(Module))
   9  230  └───       goto #4 if not %8
  10  231  3 ──       __module__@_19 = obj
  11  234  4 ┄─       Base.Docs.initmeta(__module__@_19)
  12  235  │    %12 = Base.Docs.meta(__module__@_19)
  13  235  │    %13 = ($(QuoteNode(Base.Docs.MultiDoc)))()
  14  235  │          m = Base.get!(%12, b, %13)
  15  236  │    %15 = Base.getproperty(m, :docs)
  16  236  │    %16 = Base.haskey(%15, sig)
  17  236  └───       goto #23 if not %16
  18  240  5 ── %18 = __module__@_19 === $(QuoteNode(Main))
  19  240  └───       goto #7 if not %18
  20  240  6 ──       goto #22
  21  370  7 ──       Core.NewvarNode(:(msg))
  22  370  │          Core.NewvarNode(:(kwargs))
  23  370  │          Core.NewvarNode(:(line))
  24  370  │          Core.NewvarNode(:(file))
  25  370  │          Core.NewvarNode(:(id))
  26  370  │          Core.NewvarNode(:(logger))
  27  370  │          Core.NewvarNode(:(_module))
  28  370  │          Core.NewvarNode(:(group))
  29  371  │          level = $(QuoteNode(Warn))
  30  372  │          std_level = Base.convert($(QuoteNode(Base.CoreLogging.LogLevel)), level)
  31  373  │    %31 = std_level
  32  373  │    %32 = Base.getindex($(QuoteNode(Base.RefValue{Base.CoreLogging.LogLevel}(Debug))))
  33  373  │    %33 = %31 >= %32
  34  373  └───       goto #21 if not %33
  35  374  8 ──       group = :Docs
  36  375  │          _module = Base.Docs
  37  376  │          logger = Base.CoreLogging.current_logger_for_env(std_level, group, _module)
  38  377  │    %38 = logger === $(QuoteNode(nothing))
  39  377  │    %39 = !%38
  40  377  └───       goto #21 if not %39
  41  378  9 ──       id = :Base_Docs_4352b6d8
  42* 381  │    %42 = Base.CoreLogging._invoked_shouldlog(logger, level, _module, group, id)
  43  381  └───       goto #21 if not %42
  44  382  10 ─       file = "docs/Docs.jl"
  45  383  └───       line = 240
  46  359  11 ─ %46 = $(Expr(:enter, #14))
  47  360  12 ─       msg = Base.string("Replacing docs for `", b, " :: ", sig, "` in module `", __module__@_19, "`")
  48  361  │          kwargs = ($(QuoteNode(NamedTuple)))()
  49  362  │          @_20 = true
  50  362  └───       $(Expr(:leave, 1))
  51  362  13 ─       goto #16
  52  362  14 ┄       $(Expr(:leave, 1))
  53  362  15 ─       err = $(Expr(:the_exception))
  54  364  │          Base.CoreLogging.logging_error(logger, level, _module, group, id, file, line, err, true)
  55  365  │          @_20 = false
  56  365  └───       $(Expr(:pop_exception, :(%46)))
  57  365  16 ┄       goto #21 if not @_20
  58  365  17 ─ %58 = ($(QuoteNode(NamedTuple)))()
  59  365  │    %59 = Base.merge(%58, kwargs)
  60  365  │    %60 = Base.isempty(%59)
  61  365  └───       goto #19 if not %60
  62  365  18 ─       Base.CoreLogging.handle_message(logger, level, msg, _module, group, id, file, line)
  63  365  └───       goto #20
  64  365  19 ─ %64 = Core.kwfunc($(QuoteNode(Base.CoreLogging.handle_message)))
  65  365  │    %65 = logger
  66  365  │    %66 = level
  67  365  │    %67 = msg
  68  365  │    %68 = _module
  69  365  │    %69 = group
  70  365  │    %70 = id
  71  365  │    %71 = file
  72  365  └───       (%64)(%59, $(QuoteNode(Base.CoreLogging.handle_message)), %65, %66, %67, %68, %69, %70, %71, line)
  73  365  20 ┄       goto #21
  74  391  21 ┄       $(QuoteNode(nothing))
  75  240  22 ┄       goto #24
  76  244  23 ─ %76 = Base.getproperty(m, :order)
  77  244  └───       Base.push!(%76, sig)
  78  246  24 ┄ %78 = Base.getproperty(m, :docs)
  79  246  │          Base.setindex!(%78, str, sig)
  80  247  │    %80 = Base.getproperty(str, :data)
  81  247  │          Base.setindex!(%80, b, :binding)
  82  248  │    %82 = Base.getproperty(str, :data)
  83  248  │          Base.setindex!(%82, sig, :typesig)
  84  249  └───       return b
__module__ = Pkg.LazilyInitializedFields
b = Pkg.LazilyInitializedFields.init!
str = DocStr(svec("    init!(a, s::Symbol)\n\nFunction version of [@init!](@ref).\n"), nothing, Dict{Symbol, Any}(:module=>Pkg.LazilyInitializedFields, :linenumber=>107, :path=>"[...]/usr/share/julia/stdlib/v1.7/Pkg/ext/LazilyInitializedFields/LazilyInitializedFields.jl"))
sig = Union{Tuple{T}, Tuple{T, Symbol, Any}} where T
m = MultiDoc(Type[Union{Tuple{T}, Tuple{T, Symbol, Any}} where T], IdDict{Any, Any}(Union{Tuple{T}, Tuple{T, Symbol, Any}} where T=>DocStr(svec("    init!(a, s::Symbol)\n\nFunction version of [@init!](@ref).\n"), nothing, Dict{Symbol, Any}(:typesig=>Union{Tuple{T}, Tuple{T, Symbol, Any}} where T, :module=>Pkg.LazilyInitializedFields, :linenumber=>107, :binding=>Pkg.LazilyInitializedFields.init!, :path=>"[...]/usr/share/julia/stdlib/v1.7/Pkg/ext/LazilyInitializedFields/LazilyInitializedFields.jl"))))
obj = init!
id = :Base_Docs_4352b6d8
logger = ConsoleLogger(IOBuffer(data=UInt8[...], readable=false, writable=false, seekable=false, append=false, size=0, maxsize=0, ptr=1, mark=-1), Info, default_metafmt, true, 0, Dict{Any, Int64}())
_module = Base.Docs
group = :Docs
std_level = Warn
level = Warn
caller: Pkg.LazilyInitializedFields
call_expr = :((invoke)(Base.CoreLogging.shouldlog, Tuple{Logging.ConsoleLogger, Base.CoreLogging.LogLevel, Module, Symbol, Symbol}, Logging.ConsoleLogger(IOBuffer(data=UInt8[...], readable=false, writable=false, seekable=false, append=false, size=0, maxsize=0, ptr=1, mark=-1), Info, Logging.default_metafmt, true, 0, Dict{Any, Int64}()), Warn, Base.Docs, Docs, Base_Docs_4352b6d8))

[KristofferC]

JuliaDebug/JuliaInterpreter.jl#535 (comment) might be related.

[t-bltg]

Reduced isolated reproducer:

using Revise

main() = begin
  for (i, (mod, file)) in enumerate(Base._included_files)
    endswith(file, "sysimg.jl") && continue
    basename(file) == "LazilyInitializedFields.jl" || continue
    file = Revise.fixpath(file)
    mexs = Revise.parse_source(file, mod)
    Revise.instantiate_sigs!(mexs; always_rethrow=true)
  end
  return
end

main()

[t-bltg]

This (horrible) diff using try - catch (bad, bad, bad) solves the issue and passes the JuliaInterpreter tests (unfortunately #695 (comment) fails JuliaInterpreter tests). Using hasfield(typeof(...)) instead of try - catch fails as well.

diff

diff --git a/src/interpret.jl b/src/interpret.jl
index 452abeb..a858688 100644
--- a/src/interpret.jl
+++ b/src/interpret.jl
@@ -45,25 +45,34 @@ macro lookup(args...)
         frame, node = args
     end
     nodetmp = gensym(:node)  # used to hoist, e.g., args[4]
-    if havemod
-        fallback = quote
-            isa($nodetmp, Symbol) ? getfield($(esc(mod)), $nodetmp) :
-            $nodetmp
-        end
+    fallback = if havemod
+        :(isa($nodetmp, Symbol) ? getfield($(esc(mod)), $nodetmp) : $nodetmp)
     else
-        fallback = quote
-            $nodetmp
-        end
+        :($nodetmp)
     end
+    frametmp = gensym(:frame)
     quote
         $nodetmp = $(esc(node))
-        isa($nodetmp, SSAValue) ? lookup_var($(esc(frame)), $nodetmp) :
-        isa($nodetmp, GlobalRef) ? lookup_var($(esc(frame)), $nodetmp) :
-        isa($nodetmp, SlotNumber) ? lookup_var($(esc(frame)), $nodetmp) :
-        isa($nodetmp, QuoteNode) ? $nodetmp.value :
-        isa($nodetmp, Symbol) ? getfield(moduleof($(esc(frame))), $nodetmp) :
-        isa($nodetmp, Expr) ? lookup_expr($(esc(frame)), $nodetmp) :
-        $fallback
+        $frametmp = $(esc(frame))
+        if isa($nodetmp, SSAValue)
+            lookup_var($frametmp, $nodetmp)
+        elseif isa($nodetmp, GlobalRef)
+            lookup_var($frametmp, $nodetmp)
+        elseif isa($nodetmp, SlotNumber)
+            lookup_var($frametmp, $nodetmp)
+        elseif isa($nodetmp, QuoteNode)
+            $nodetmp.value
+        elseif isa($nodetmp, Symbol)
+            try
+                getfield(moduleof($frametmp), $nodetmp)
+            catch
+                $nodetmp
+            end
+        elseif isa($nodetmp, Expr)
+            lookup_expr($frametmp, $nodetmp)
+        else
+            $fallback
+        end
     end
 end

I'm out of ideas atm :/

[timholy]

Thanks for the tip, @KristofferC. Fix in JuliaInterpreter coming (EDIT: JuliaDebug/JuliaInterpreter.jl#540).

[t-bltg]

It's awesome to see Testing Revise tests passed back 🎉
Thanks for the quick fix !