World age issue when precompiling and redirecting the logger stream

[fredrikekre]

See JuliaLang/IJulia.jl#677. IJulia sets the global logger with its own stream which causes the following during precompilation of a package:

MethodError: no method matching pipe_writer(::IJulia.IJuliaStdio{Base.PipeEndpoint})
The applicable method may be too new: running in world age 27495, while current world is 27509.
Closest candidates are:
  pipe_writer(::IJulia.IJuliaStdio) at /home/fredrik/.julia/dev/IJulia/src/stdio.jl:15 (method too new to be called from this world context.)
  pipe_writer(!Matched::Base.ProcessChain) at process.jl:344
  pipe_writer(!Matched::Base.Process) at process.jl:332

Here is another repro from @pfitzseb:

julia> using Logging
       struct MyLogger <: AbstractLogger end
       Logging.shouldlog(::MyLogger, level, _module, group, id) = false
       Logging.min_enabled_level(::MyLogger) = Logging.BelowMinLevel

shell> rm -rf /home/fredrik/.julia/compiled/v0.7/BenchmarkTools/

julia> with_logger(MyLogger()) do
           @eval using BenchmarkTools
       end
ERROR: MethodError: no method matching shouldlog(::MyLogger, ::LogLevel, ::Module, ::Symbol, ::Symbol)
The applicable method may be too new: running in world age 27495, while current world is 27499.
Closest candidates are:
  shouldlog(::MyLogger, ::Any, ::Any, ::Any, ::Any) at REPL[0]:3 (method too new to be called from this world context.)
  shouldlog(::NullLogger, ::Any...) at logging.jl:83
  shouldlog(::SimpleLogger, ::Any, ::Any, ::Any, ::Any) at logging.jl:507
  ...
Stacktrace:
 [1] macro expansion at ./logging.jl:306 [inlined]
 [2] compilecache(::Base.PkgId) at ./loading.jl:1169
 [3] _require(::Base.PkgId) at ./loading.jl:942
 [4] require(::Base.PkgId) at ./loading.jl:838
 [5] require(::Module, ::Symbol) at ./loading.jl:833
 [6] eval at ./boot.jl:319 [inlined]
 [7] (::getfield(Main, Symbol("##3#4")))() at ./REPL[2]:2
 [8] with_logstate(::getfield(Main, Symbol("##3#4")), ::Base.CoreLogging.LogState) at ./logging.jl:385
 [9] with_logger(::Function, ::MyLogger) at ./logging.jl:481
 [10] top-level scope at none:0

[pfitzseb]

This is a relatively recent regression; I can't repro this on

Julia Version 0.7.0-beta.113
Commit 324e525786 (2018-07-02 03:28 UTC)

[fredrikekre]

Perhaps related to some of @StefanKarpinski's recent code-loading changes?

[StefanKarpinski]

None of my changes should affect anything world-age-related. Maybe #27549?

[pfitzseb]

Regression seems to have occurred sometime between

Julia Version 0.7.0-beta.113
Commit 324e525786 (2018-07-02 03:28 UTC)

and

Julia Version 0.7.0-beta.138
Commit 429e2d5070 (2018-07-04 14:10 UTC)

but that's all the bisecting I'm gonna do today.

Edit: 027e344 seems kinda relevant judging by the commit message.

[StefanKarpinski]

Ah yes, #27894 is actually what I meant to find above.

[fredrikekre]

Indeed, git bisect points to 027e344 @JeffBezanson

A trivial fix would be to change

julia/base/loading.jl

Line 1173 in 3791357

@logmsg verbosity "Recompiling stale cache file $cachefile for module $name"

and

julia/base/loading.jl

Line 1175 in 3791357

@logmsg verbosity "Precompiling module $name"

to good old printlns

[vtjnash]

Ah, yes. We might need to revert that commit, or at least make it only applicable inside the precompile process children

[pfitzseb]

Should that commit be reverted or is there a solution that keeps the performance improvements and doesn't break things, @JeffBezanson?