# Different Logging output between Juno Execute and Julia REPL
**URL:** https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933
**Category:** New to Julia
**Created:** [November 10, 2019, 11:59pm UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933 "2019-11-10T23:59:05Z")
**Posts on this page:** 15
**Page:** 1
### Author:  [@venuur](https://discourse.julialang.org/u/venuur)
#### Post date: [November 10, 2019, 11:59pm UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/1 "2019-11-10T23:59:05Z")
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:
1. Create new package via `generate LoggerProblem` at the julia repl.
2. Open the new folder `LoggerProblem` in Juno.
3. Change `src/LoggerProblem.jl` to contain the following:
```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
```
1. Create a new file `scratch.jl` in the package directory with the following contents:
```julia
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.
```julia
┌ 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
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?
---
### Author:  [@pfitzseb](https://discourse.julialang.org/u/pfitzseb)
#### Post date: [November 11, 2019, 9:24am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/2 "2019-11-11T09:24:41Z")
I can’t repro this. Your code (slightly adapted to fit into one file)
```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
using Logging
logger = ConsoleLogger(stdout, Logging.Debug)
old_logger = global_logger(logger)
LoggerProblem.log_example()
global_logger(old_logger)
LoggerProblem.log_example()
```
produces
```julia
┌ 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
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
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](https://github.com/JunoLab/Atom.jl/blob/c19d207846a45efbcc7301711f766dd61bbaa82b/src/progress.jl#L75-L76). We could conceivably fix this by instead using
```julia
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.
---
### Author:  [@cserteGT3](https://discourse.julialang.org/u/cserteGT3)
#### Post date: [November 11, 2019, 10:00am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/3 "2019-11-11T10:00:29Z")
I had (and have) somewhat similar issue with Revise in Juno. Maybe related?
> [@Logging issue with Juno and Revise](https://discourse.julialang.org/t/logging-issue-with-juno-and-revise/26280):
>
> I’ve created a custom logger, which doesn’t show @debug messages with Revise in Juno. If I include() the source file, it works in the REPL and Juno too. If I includet with Revise, then works in REPL, but not in Juno. logtest.jl: module LogT using Logging using Logging: default\_logcolor export nosource\_debuglogger, nosource\_infologger, sourced\_debuglogger, sourced\_infologger function nosource\_metafmt(level, \_module, group, id, file, line) color = default\_logcolo…
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 12, 2019, 7:20am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/4 "2019-11-12T07:20:23Z")
> [@pfitzseb](#):
>
> There is some weirdness when changing the global logger in one block though:
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.
> [@pfitzseb](#):
>
> 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.
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.)
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 12, 2019, 7:32am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/5 "2019-11-12T07:32:27Z")
> [@pfitzseb](#):
>
> The problem here is that `min_enabled_level` is only update once per logger, [but relies on the global logger’s state in Juno](https://github.com/JunoLab/Atom.jl/blob/c19d207846a45efbcc7301711f766dd61bbaa82b/src/progress.jl#L75-L76). We could conceivably fix this
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()`:
```julia
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.)
> [@pfitzseb](#):
>
> just stop (ab-)using the logging system for progress bars
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.
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 12, 2019, 7:54am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/6 "2019-11-12T07:54:24Z")
> [@pfitzseb](#):
>
> Ideally we’d have a logger stack (a bit like the display system)
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](https://github.com/oxinabox/LoggingExtras.jl/issues/23#issuecomment-546439791) / [Return from handle\_message as to if message was handled or not by oxinabox · Pull Request #25 · JuliaLogging/LoggingExtras.jl · GitHub](https://github.com/oxinabox/LoggingExtras.jl/pull/25)
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.
---
### Author:  [@pfitzseb](https://discourse.julialang.org/u/pfitzseb)
#### Post date: [November 12, 2019, 8:58am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/7 "2019-11-12T08:58:18Z")
> [@c42f](#):
>
> I can’t reproduce this with the normal REPL.
Yeah, sorry, I wasn’t quite clear – this only happens in Juno.
> [@c42f](#):
>
> 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()` :
We’re doing that, but
```julia
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.
> [@c42f](#):
>
> 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.
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).
---
### Author:  [@oxinabox](https://discourse.julialang.org/u/oxinabox)
#### Post date: [November 12, 2019, 9:18am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/8 "2019-11-12T09:18:01Z")
> [@pfitzseb](#):
>
> 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).
Thats this bit which all composable loggers (i.e. not pure sinks) in LoggingExtras call.
>
In the PR it is one of the was `handle_message` can return `WasHandled(false)` see this line:
>
>
> Will close #23
>
> I am not sure on the name of the struct.
> Possibly should be …\`HandlerResponse\`?
>
>
> cc @tkf
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 12, 2019, 9:20am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/9 "2019-11-12T09:20:48Z")
> [@pfitzseb](#):
>
> fails because `min_enabled_level` doesn’t take into account the changed global logger
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).
> [@pfitzseb](#):
>
> Ideally it would be possible to fall through to the next logger when `shoudlog` or `min_enabled_logger` return false, no?
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.)
---
### Author:  [@tkf](https://discourse.julialang.org/u/tkf)
#### Post date: [November 12, 2019, 9:38pm UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/10 "2019-11-12T21:38:54Z")
> [@c42f](#):
>
>  pfitzseb:
>
> > just stop (ab-)using the logging system for progress bars
>
> 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
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.
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 13, 2019, 12:16am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/11 "2019-11-13T00:16:06Z")
> [@tkf](#):
>
> we don’t need to route anything because it’s an API completely separate from normal logging
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.
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 13, 2019, 1:42am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/12 "2019-11-13T01:42:31Z")
> [@tkf](#):
>
> 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?
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.
---
### Author:  [@tkf](https://discourse.julialang.org/u/tkf)
#### Post date: [November 13, 2019, 4:53am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/13 "2019-11-13T04:53:08Z")
> [@c42f](#):
>
> logging is about capturing a structured event stream
_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](https://www.fluentd.org/) and metric monitoring systems like [prometheus](https://prometheus.io/) 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.
> [@c42f](#):
>
> 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”
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”.
---
### Author:  [@c42f](https://discourse.julialang.org/u/c42f)
#### Post date: [November 14, 2019, 12:52am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/14 "2019-11-14T00:52:22Z")
> [@tkf](#):
>
> 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.
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 `LogRecord`s 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](https://github.com/JuliaLang/julia/pull/33711))
---
### Author:  [@tkf](https://discourse.julialang.org/u/tkf)
#### Post date: [November 14, 2019, 2:34am UTC](https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/15 "2019-11-14T02:34:56Z")
> [@c42f](#):
>
> or if we do so, the proliferation of different `LogRecord` types.
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?
> [@c42f](#):
>
> The system tries hard to support early filtering based on partially complete `LogRecord` s
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…