World age problem with global_logger and tasks launched before logger definition

[tkf]

It seems global_logger does not work well with tasks in the following scenario:

1. A task using the logger is launched.
2. A new logger is defined (e.g., via import).
3. The new logger is set as the global logger.
4. The task tries to log something.

As an example, running the following code in a fresh julia process (i.e., the one that has not imported TerminalLoggers yet) throws a method error.

using Logging

ch = Channel() do ch
    for _ in 1:2
        try
            @info take!(ch)
        catch err
            bt = catch_backtrace()
            with_logger(ConsoleLogger()) do
                @error "`@info` threw" exception = (err, bt)
            end
        end
    end
end

put!(ch, "hello to ConsoleLogger")

using TerminalLoggers
# yield()

global_logger(TerminalLogger())
put!(ch, "hello to TerminalLogger")

Output:

[ Info: hello to ConsoleLogger
┌ Error: `@info` threw
│   exception =
│    MethodError: no method matching shouldlog(::TerminalLogger, ::Base.CoreLogging.LogLevel, ::Module, ::String, ::Symbol)
│    The applicable method may be too new: running in world age 26999, while current world is 27001.
│    Closest candidates are:
│      shouldlog(::TerminalLogger, ::Any, ::Any, ::Any, ::Any) at /home/takafumi/.julia/dev/TerminalLoggers/src/TerminalLogger.jl:40 (method too new to be called from this world context.)
│      shouldlog(::Base.CoreLogging.NullLogger, ::Any...) at logging.jl:84
│      shouldlog(::Base.CoreLogging.SimpleLogger, ::Any, ::Any, ::Any, ::Any) at logging.jl:529
│      ...
│    Stacktrace:
│     [1] macro expansion at ./logging.jl:316 [inlined]
│     [2] (::var"#3#5")(::Channel{Any}) at /home/takafumi/demo.jl:6
│     [3] (::Base.var"#630#631"{var"#3#5",Channel{Any}})() at ./channels.jl:129
└ @ Main ~/junk/2019/11/15-174444.jl:10
ERROR: LoadError: InvalidStateException("Channel is closed.", :closed)
Stacktrace:
 [1] try_yieldto(::typeof(Base.ensure_rescheduled), ::Base.RefValue{Task}) at ./task.jl:611
 [2] wait() at ./task.jl:668
 [3] wait(::Base.GenericCondition{ReentrantLock}) at ./condition.jl:106
 [4] put_unbuffered(::Channel{Any}, ::String) at ./channels.jl:350
 [5] put!(::Channel{Any}, ::String) at ./channels.jl:325
 [6] top-level scope at /home/takafumi/demo.jl:22
 [7] include(::Module, ::String) at ./Base.jl:377
 [8] exec_options(::Base.JLOptions) at ./client.jl:296
 [9] _start() at ./client.jl:492

Here I'm using https://github.com/c42f/TerminalLoggers.jl (as that's the easiest to set up) but it happens with other packages like https://github.com/oxinabox/LoggingExtras.jl.

Note that uncommenting # yield() fixes the problem. So, as a short term solution, is calling yield() inside global_logger(logger) reasonable? Or maybe implicitly call yield() after using/import?

As a long term solution, maybe start discouraging the use of global_logger and add an API to set up a logger for the RPL, as @c42f suggested in https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/5? IIUC, with this solution, the task-local logger is inherited to the "background" task at the time it is started and pre-launched tasks will not try to log to the logger that is defined after it is launched. But I'm not 100% sure this is the desired behavior. Maybe it is desirable to be able to swap the logger after it is started?

[c42f]

Yes it seems increasingly clear that having global_logger as a recommended API for the typical user causes various problems. Thanks for clearly documenting this particular one.

I think a technical workaround for world age is to have a fixed root logger installed on the root task during system init, and to make this a trivial shim which uses invokelatest to call into some user-replaceable global logger. That adds some dispatch overhead but at least it would work! The application author can opt out by using with_logger as a wrapper around their main application.

It would be more satisfying to remove global_logger entirely and "only use with_logger" so that the logging tree strictly follows the task tree. But I'm not yet sure this can work out in all cases. For example, consider the way Revise is added to the REPL during early init. It seems valid for people to want to swap the logger used by Revise at runtime, or at the very least to change the way it filters messages. Hmm, though looking at the Revise code it's clearly hacking at the REPL internals so that could probably be solved by just adding more hooks to the REPL for running user code.

[c42f]

Note that uncommenting # yield() fixes the problem

This seems pretty weird actually and I don't understand why this happens nor whether we can rely on it. But then again, the world age system isn't something I know much about yet. Do you know why this happens?

[tkf]

a trivial shim which uses invokelatest to call into some user-replaceable global logger

This makes sense. Also, I suppose invokelatest-based shim logger is the only way to do this? I mean, even if global_logger inside REPL task means to replace its task-local logger, I suppose we still have the same world age issue? Or, can there be an API to re-launch the task in the new world age? This means that loggers used by Revise etc. will not be updated, though.

Note that uncommenting # yield() fixes the problem

This seems pretty weird actually

I have no idea why yield works. It was something I noticed because I couldn't reproduce the failure inside the REPL.

[c42f]

The yield doesn't seem to help on julia 1.2, but on 1.3-rc4 and on a fairly recent 1.4-DEV it does. Oddly enough, this is despite the method table listing the appropriate shouldlog method as having a later primary_world age than the value of ccall(:jl_get_tls_world_age, UInt, ()) within the async child task.

[NHDaly]

This makes sense. Also, I suppose invokelatest-based shim logger is the only way to do this? I mean, even if global_logger inside REPL task means to replace its task-local logger, I suppose we still have the same world age issue? Or, can there be an API to re-launch the task in the new world age? This means that loggers used by Revise etc. will not be updated, though.

We are still seeing this issue.

Is it feasible to just have @info / @warn / etc make all calls to the logger via invokelatest()? Logging is going to be slow anyway. Does anyone see any harm in that?

[vtjnash]

I thought most calls (that the user is permitted to overload) are handled with invokelatest now. Did we miss one?

[vtjnash]

julia> put!(ch, "hello to TerminalLogger")
[ Info: hello to TerminalLogger
"hello to TerminalLogger"

[NHDaly]

Oh interesting. i'm not sure. Fixed on 1.8? Or fixed on master? I'll try to dig up some logs where we've seen this.

[NHDaly]

CC: @dewilson, @quinnj and @nickrobinson251 who have all seen this, right?

[NHDaly]

For example, here is one we saw today, on julia v1.8.2:

ERROR: MethodError: no method matching shouldlog(::TransactionLogging.LocalLogger, ::Base.CoreLogging.LogLevel, ::Module, ::Symbol, ::Symbol)
The applicable method may be too new: running in world age 32015, while current world is 32286.
Closest candidates are:
  shouldlog(::TransactionLogging.LocalLogger, ::Any, ::Any, ::Any, ::Any) at ~/packages/TransactionLogging/src/local_logger.jl:52 (method too new to be called from this world context.)
  shouldlog(::LoggingExtras.LevelOverrideLogger, ::Any, ::Any...) at ~/.julia/packages/LoggingExtras/5k9PW/src/CompositionalLoggers/overridelogger.jl:17
  shouldlog(::LoggingExtras.ActiveFilteredLogger, ::Any...) at ~/.julia/packages/LoggingExtras/5k9PW/src/CompositionalLoggers/activefiltered.jl:37
  ...
Stacktrace:
  [1] _invoked_shouldlog
    @ ./logging.jl:78 [inlined]
  [2] macro expansion
    @ ./logging.jl:381 [inlined]
  [3] report_empty_testsets(ti::TestItem, ts::Test.DefaultTestSet)
    @ ReTestItems ~/.julia/packages/ReTestItems/Go9Yr/src/log_capture.jl:253
  [4] _runtests_in_current_env(shouldrun::Function, paths::Tuple{String}, projectfile::String, nworkers::Int64, nworker_threads::Int64, worker_init_expr::Expr, testitem_timeout::Int64, retries::Int64, verbose_results::Bool, debug::Int64, report::Bool, logs::Symbol)
    @ ReTestItems ~/.julia/packages/ReTestItems/Go9Yr/src/ReTestItems.jl:251

[vtjnash]

e84634e. I don't think we are going to be backport it.

[NHDaly]

Aha! Thank you, indeed it's been fixed! Neat. :)

It's just the one part of the change that we'd need, here:

Would we consider that a bug fix? Would it make sense to backport to 1.9.1?
CC: @quinnj