Different Logging output between Juno Execute and Julia REPL

venuur · November 10, 2019, 11:59pm

For some reason @debug messages are appearing when I run a modules function via shift+enter in Juno with Julia 1.2 but not when I run the function directly on the REPL.

Here’s the minimal setup:

Create new package via generate LoggerProblem at the julia repl.
Open the new folder LoggerProblem in Juno.
Change src/LoggerProblem.jl to contain the following:

module LoggerProblem

export log_example

function log_example()
    @debug "This statement should appear at debug level."
    @warn "This statement should appear at warn level."
end

end # module

Create a new file scratch.jl in the package directory with the following contents:

import Pkg
Pkg.activate(".")
using Revise
using LoggerProblem
using Logging


logger = ConsoleLogger(stdout, Logging.Debug)
old_logger = global_logger(logger)

log_example()

If you run each line using shift+enter you get the following output.

┌ Debug: This statement should appear at debug level.
└ @ LoggerProblem C:\Users\carlm\workspace\julia-lisp\LoggerProblem\LoggerProblem\src\LoggerProblem.jl:6
┌ Warning: This statement should appear at warn level.
└ @ LoggerProblem C:\Users\carlm\workspace\julia-lisp\LoggerProblem\LoggerProblem\src\LoggerProblem.jl:7

However, if I run the next line I get different results:

julia> log_example()
┌ Warning: This statement should appear at warn level.
└ @ LoggerProblem C:\Users\carlm\workspace\julia-lisp\LoggerProblem\LoggerProblem\src\LoggerProblem.jl:7

I’ve read several posts and the documentation, but I can’t tell what’s going wrong. Any suggestions on where to look next for troubleshooting?

pfitzseb · November 11, 2019, 9:24am

I can’t repro this. Your code (slightly adapted to fit into one file)

module LoggerProblem

export log_example

function log_example()
    @debug "This statement should appear at debug level."
    @warn "This statement should appear at warn level."
end

end # module

using Logging
logger = ConsoleLogger(stdout, Logging.Debug)
old_logger = global_logger(logger)
LoggerProblem.log_example()
global_logger(old_logger)
LoggerProblem.log_example()

produces

┌ Debug: This statement should appear at debug level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:6
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:7
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:7
julia> logger = ConsoleLogger(stdout, Logging.Debug)
ConsoleLogger(Base.TTY(RawFD(0x00000018) open, 0 bytes waiting), Debug, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> old_logger = global_logger(logger)
ConsoleLogger(Base.TTY(RawFD(0x0000001a) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> LoggerProblem.log_example()
┌ Debug: This statement should appear at debug level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:6
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:7

julia> global_logger(old_logger)
ConsoleLogger(Base.TTY(RawFD(0x00000018) open, 0 bytes waiting), Debug, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> LoggerProblem.log_example()
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:4774:7

in Juno. The REPL output is exactly the same:

julia> module LoggerProblem

       export log_example

       function log_example()
           @debug "This statement should appear at debug level."
           @warn "This statement should appear at warn level."
       end

       end # module
Main.LoggerProblem

julia> using Logging

julia> logger = ConsoleLogger(stdout, Logging.Debug)
ConsoleLogger(Base.TTY(RawFD(0x00000018) open, 0 bytes waiting), Debug, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> old_logger = global_logger(logger)
ConsoleLogger(Base.TTY(RawFD(0x0000001a) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> LoggerProblem.log_example()
┌ Debug: This statement should appear at debug level.
└ @ Main.LoggerProblem REPL[1]:6
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem REPL[1]:7

julia> global_logger(old_logger)
ConsoleLogger(Base.TTY(RawFD(0x00000018) open, 0 bytes waiting), Debug, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> LoggerProblem.log_example()
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem REPL[1]:7

There is some weirdness when changing the global logger in one block though:

julia> begin
           logger = ConsoleLogger(stdout, Logging.Debug)
           old_logger = global_logger(logger)
           LoggerProblem.log_example()
           global_logger(old_logger)
           LoggerProblem.log_example()
       end
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:7
┌ Warning: This statement should appear at warn level.
└ @ Main.LoggerProblem untitled-b1939cc8a3fc9b574cb2a0b15f6dd330:7

In general, I’d recommend using with_logger instead of explicitly changing the global logger.

The problem here is that min_enabled_level is only update once per logger, but relies on the global logger’s state in Juno. We could conceivably fix this by instead using

Logging.min_enabled_level(j::JunoProgressLogger) = Debug

(or whatever the minimal log level is), but that probably has performance implications.

Ideally we’d have a logger stack (a bit like the display system) for cases such as this (any thoughts on this, @c42f?), or just stop (ab-)using the logging system for progress bars.

cserteGT3 · November 11, 2019, 10:00am

I had (and have) somewhat similar issue with Revise in Juno. Maybe related?

c42f · November 12, 2019, 7:20am

I can’t reproduce this with the normal REPL.

One way I could imagine this happening is if you’re running from within Atom and your Atom REPL has a task logger installed for your REPL task (ie, via with_logger()).

The short term solution is as you say: just use with_logger() rather than messing with the global logger.

A few people (@oxinabox, @tkf and myself at least) have started thinking about composable log routing, so I’m optimistic that there will eventually be a cleaner recommendation for many of these things. I don’t have a great coherent solution to offer you right now though. (You can check out LoggingExtras.jl for some log routing ideas and we have very recently started prototyping more terminal UI tools in TerminalLogging.jl.)

c42f · November 12, 2019, 7:32am

Yes, this is definitely problematic having a mutable min_enabled_level. Luckily the fix should be rather simple if you systematically wrap each Juno REPL command in a with_logger():

with_logger(some_juno_logger) do
    $user_code
end

The standard REPL should probably also do something similar. Then the “repl logger” can be replaced/mutated at will, without falling afoul of the min_enabled_level optimization.

(Edit: Going in this direction systematically, one has to wonder what the utility of the global logger is. I think it’s probably going to be replaced in the longer term, but I feel that the most coherent design depends on how/whether tasks nest in our concurrency model which seems very much to-be-decided.)

I hope you don’t have to do this by the way I still think it can be a great solution for unifying progress bars in a way which allows packages to emit progress messages without any dependencies.

c42f · November 12, 2019, 7:54am

On second thought, I do have a cross reference for this to some WIP: Make handle_message return true/false depending on if accepted · Issue #23 · JuliaLogging/LoggingExtras.jl · GitHub / Return from handle_message as to if message was handled or not by oxinabox · Pull Request #25 · JuliaLogging/LoggingExtras.jl · GitHub

To summarize, the idea is that handle_message could be changed to return “some indication” of whether a logger has successfully handled a message, which would allow for a systematic “handle or pass it on” style which you may like for just pulling out progress messages in the Juno progress display while passing the rest onward.

pfitzseb · November 12, 2019, 8:58am

Yeah, sorry, I wasn’t quite clear – this only happens in Juno.

We’re doing that, but

with_logger(JunoLogger()) do
  logger = ConsoleLogger(stdout, Logging.Debug)
  old_logger = global_logger(logger)
  LoggerProblem.log_example()
  global_logger(old_logger)
  LoggerProblem.log_example()
end

still fails because min_enabled_level doesn’t take into account the changed global logger.

Ideally it would be possible to fall through to the next logger when shoudlog or min_enabled_logger return false, no? Passing to the next logger in handle_message is already mostly possible (only with three different logger though, I think).

oxinabox · November 12, 2019, 9:18am

Thats this bit which all composable loggers (i.e. not pure sinks) in LoggingExtras call.

github.com

JuliaLogging/LoggingExtras.jl/blob/76edd6f0a2e61de1b583e267f9720587b3b64d9e/src/LoggingExtras.jl#L22-L31


      
          function comp_shouldlog(logger, args...)
              level = first(args)
              min_enabled_level(logger) <= level && shouldlog(logger, args...)
          end
          
          # For checking if child logger will take the message you are sending
          function comp_handle_message_check(logger, args...; kwargs...)
              level, message, _module, group, id, file, line = args
              return comp_shouldlog(logger, level, _module, group, id)
          end

In the PR it is one of the was handle_message can return WasHandled(false) see this line:

c42f · November 12, 2019, 9:20am

Oh I see; you’re grouping the lines as a single block of code to run. Does this make for other inconsistencies in terms of how top level expressions are normally interpreted in a file? Regardless, I think the solution must be to use with_logger if people really want to swap out their logger half way through a block. Viewed in this light, the global logger looks more and more like a kludge which can’t be relied on (though perhaps a global fallback log sink could work out better).

Not in the frontend. But the backends may implement some fallthrough for shouldlog if they desire. (btw min_enabled_level was only meant as an optimization to give the frontend a little type stable knowledge of installed logger because the current logger is inherently an Any to inference.)

tkf · November 12, 2019, 9:38pm

Just to think out side the box (or maybe I’m just late to the discussion), but what is the advantage of using logging system to record progress events? In principle, there can be a simple package that sets up a global Channel or a hook registry so that we can have various frontends and backends. This way, we don’t need to route anything because it’s an API completely separate from normal logging.

c42f · November 13, 2019, 12:16am

It’s certainly possible!

In my mind, logging is about capturing a structured event stream from your running code; progress events match this pattern just as much as other types of events. So I think that progress reporting is an excellent conceptual match for the logging system.

c42f · November 13, 2019, 1:42am

To be clear, I do think this is a good question. It’s certainly possible to fall short of what I think is the high level design goal “a general system for recording events related to program execution and for filtering / routing such events”. In the current system the biggest difficulty seems to be the open ended nature of the event structure (the meaning of the key value pairs; the API for log levels; the allowed types / precise semantic for the message itself; the precise semantic for the message group, etc). But the open ended nature is also an asset which gives people the freedom to try various ideas.

Prototyping an “ideal” progress logging frontend and backend separate from any constraints of the logging system could be very useful to show where the logging system could be improved.

tkf · November 13, 2019, 4:53am

Usually in other languages (meaning that it doesn’t mean Julia ecosystem shouldn’t aim high), my impression is that “logging” is about recording human readable messages and structured metadata is secondary. For example, big logging frameworks like fluentd and metric monitoring systems like prometheus seem to operate on different fields (though I’m not familiar at all of those things).

Structured events require handlers that can interpret them. So, at the time you are writing event sources @info ..., you are targeting a special subset of the handlers (e.g., progress, data table, timing info (like what TimerOutputs.jl does)). I feel uneasy about putting them in a single “channel” and re-route them with a complex machinery. It makes me wonder if we are creating a problem that does not exist if we change the solution.

I agree that having a general mechanism for filtering and routing is very appealing. But wouldn’t it be even better if we can decouple this from CoreLogging? That is to say, we create a pure filtering / routing framework (or just build it on top of transducers :)) and use it from CoreLogging just as one application. One of the benefits of decoupling the filtering / routing framework from logging is that it’s free to choose “event transportation” layer; e.g., it can use task_local_storage “like” CoreLogging or it can use a global Channel to have thread safety “for free”.

c42f · November 14, 2019, 12:52am

That sounds interesting for sure. The analogy between transducers and log event processing is striking as we’ve seen several times and I’ve wondered if transducers could just be used directly. There’s a few mismatches but maybe nothing essential. A couple of thoughts:

I assume we will need an appropriate LogRecord type to bundle the fields together. One thing I’ve been wondering about in creating a LogRecord type is the inability to have concrete types for the fields (or if we do so, the proliferation of different LogRecord types.)
The system tries hard to support early filtering based on partially complete LogRecords and I think this makes the API quite awkward when plugging into downstream record processing. An early iteration of the API tried to avoid this by creating a closure which would complete the log record, but IIRC Jeff was worried about the proliferation of closures when using that style (compare also https://github.com/JuliaLang/julia/pull/33711)

tkf · November 14, 2019, 2:34am

Isn’t this more-or-less what is happening ATM? handle_message would be specialized for argument types. So, I guess it is equivalent to have LogRecord with concrete field types? But maybe your main point was that we should try to write monomorphic code for compile time (and also for dynamic dispatch?) performance?

That’s a good point I missed. Level-based early filtering inherently requires at least two passes of processing pipeline/tree. It would be great if we can use closure to avoid this but it would increase compile time…

Topic		Replies	Views
Logging issue with Juno and Revise General Usage question	3	522	July 15, 2019
Log (eg depwarn) message source full path Internals & Design question	4	541	July 6, 2018
Using @debug in Atom console General Usage question	5	1497	October 4, 2018
Confused about logging New to Julia	10	3206	February 26, 2020
How to use @debug General Usage	0	461	June 13, 2019

Different Logging output between Juno Execute and Julia REPL

Related topics