Confused about logging

New to Julia
1

I’m trying to figure out how the Logging module works. I’ve browsed through the documentation and tried reading through logging.jl, but not much of this makes sense to me, unfortunately.

I saw this explanation, which includes the following example (Below is my version of trying out the code at the above link)

julia> using Logging

julia> logger = SimpleLogger(stdout, Logging.Debug)
Base.CoreLogging.SimpleLogger(Base.TTY(RawFD(0x0000000d) open, 0 bytes waiting), Debug, Dict{Any,Int64}())

julia> @info "info"
[ Info: info

julia> @debug "debug"

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

julia> @info "info"
┌ Info: info
└ @ Main REPL[7]:1

julia> @debug "debug"
┌ Debug: debug
└ @ Main REPL[8]:1

julia>

It’s not clear to me what about the line old_logger = global_logger(logger) makes the debug message visible thereafter. A SimpleLogger was created at the Logging.Debug level, but the debug message wasn’t shown until the logger was passed into global_logger. The documentation doesn’t seem to cover strange details such as this.

I would imagine there would be a way to simply specify what logging level I prefer at (for example) the top of a file. Something like set_loglevel!("Debug"). I also don’t need to call using Logging for simple applications, right? It looks like the @debug, @info, etc. macros are available without any importing.

I hope my questions are clear. Do let me know if I need to clarify anything!

Edit: I just noticed that the format of the info and debug messages changed after global_logger was called. Why is that?

2 Likes
2

The call global_logger(logger) set your new logger logger to be the global logger.

You were just creating a logger, but not telling Julia to use it.

The default logger is a TerminalLogger which has some different formatting compared to SimpleLogger.

3 Likes
3

Thank you for the quick reply! I still have some unanswered questions.

How would a simple implementation of this look in a file? Say, for example, I have an independent julia file that I want to run with some debug and info messages. Would I put the following at the top of the file?

using Logging
logger = SimpleLogger(stdout, Logging.Debug)
global_logger(logger)

This feels too chunky to include at the start of a file any time I want to use both the @debug and @info macros (and others down the road, who knows).

4

You can use @info and @debug and the other logging macros without changing the default logger provided you’ve done using Logging. You only have to set a different logger if you want that loggers’ features or pretty printing (as is the case with SimpleLogger). To execute a function with a specific logger without changing the global logger for concurrently executed code, you can use with_logger.

1 Like
5

Ok, thanks for the help! I still don’t know how to set the logging level. I also looked in the command-line arguments for julia but didn’t see anything.

6

Using those macros (@info, @debug) how do you affect the logging level? This documentation isn’t very helpful since it doesn’t explain, generally, how the environment parameter works: Logging · The Julia Language
Do I set JULIA_DEBUG to an integer as in some languages? The docs imply the value to which I set JULIA_DEBUG affects the scope in which it is applied - but something like JULIA_DEBUG="log_test.jl" doesn’t get @debug statements to come out of a file log_test.jl.

1 Like
7

May be this would be helpful? How to Change LogLevel with Logging Package? - #2 by Sukera

8

@Skoffer, that link is the same one I included at the beginning of this post. Appreciate the help though! One day I’ll get to the bottom of this :smile:

@Alex_Ellison, I did notice this command-line option:

 -g, -g <level>    Enable / Set the level of debug info generation (default level is 1 if unspecified or 2 if used without a level)

I wrote a simple script (called debug_test.jl) that calls the four main logging macros line by line.

@debug "debug"
@info "info"
@warn "warn"
@error "error"

Then tested it without the -g option and with other values.

$ julia debug_test.jl 
[ Info: info
┌ Warning: warn
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:5
┌ Error: error
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:7
$ julia -g -- debug_test.jl 
[ Info: info
┌ Warning: warn
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:5
┌ Error: error
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:7
$ julia -g 3 -- debug_test.jl 
ERROR: julia: invalid argument to -g (3)
$ julia -g 0 -- debug_test.jl 
[ Info: info
┌ Warning: warn
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:5
┌ Error: error
└ @ Main ~/code_stuff/julia_stuff/debug_test.jl:7

What values does -g expect? From the logging.jl source file, it looks like debug might be at level -1000, for some reason, but specifying this in the command line also doesn’t work. The mystery deepens!

1 Like
9

Sorry about wrong link. Now, as for the logging, first of all it has been changed on master branch, but in julia 1.3.1, these lines are important: julia/logging.jl at v1.3.1 · JuliaLang/julia · GitHub

It looks like environment control is rather rudimentary, the only thing you can do is to set JULIA_DEBUG to all

shell> JULIA_DEBUG=all julia debug_test.jl 
┌ Debug: debug
└ @ Main /tmp/debug_test.jl:1
[ Info: info
┌ Warning: warn
└ @ Main /tmp/debug_test.jl:3
┌ Error: error
└ @ Main /tmp/debug_test.jl:4

Key -g addresses debugger information, I presume and doesn’t affect logging at all.

In master branch of julia (v1.5 I guess) you can use more elaborated control for JULIA_DEBUG with include and exclude groups, so something like this should work:

In julia file you define

@debug "debug"
@info "info"
@warn "warn"
@error "error"
@warn _group=:g1 "another warning"

and in shell

shell> JULIA_DEBUG='all,!g1' julia debug_test.jl

it should produce all message including debug, but excluding last @warn which relates to :g1 group. Unfortunatelt, I can’t verify it yet, cause I do not have v1.5 locally.

1 Like
10

The -g command line flag is a compiler flag, not a logging flag:

base $ rg debug_level
options.jl
23:    debug_level::Int8

util.jl
453:    push!(addflags, "-g$(opts.debug_level)")

compiler/validation.jl
59:    if JLOptions().debug_level == 2

compiler/ssair/driver.jl
129:    if JLOptions().debug_level == 2

The macros themselves create a logging event with the associated level. To create a logging message with a custom level, use @logmsg level message where level is the logging level and message is the message you want to appear with that level. See also here.

You’ve misunderstood the documentation - setting JULIA_DEBUG=log_test will only affect the default minimum log level for a module called log_test:

log $ cat test_log.jl
module test_log

using Logging

@debug "hello from debug"
@info "hello from info"

end
log $ cat no_log.jl
module no_log

using Logging

@debug "hello from debug"
@info "hello from info"

end
log $ JULIA_DEBUG=test_log julia test_log.jl
┌ Debug: hello from debug
└ @ Main.test_log /c/Users/valentin/Documents/Projects/juliaProjects/Discourse/log/test_log.jl:5
[ Info: hello from info
log $ JULIA_DEBUG=test_log julia no_log.jl
[ Info: hello from info

Though I agree that this is somewhat poorly documented and the documentation should be improved.

Note that the way LogLevels or Logging in general works is being considered for some or more rework, as that’s a leftover from the 0.x days.

2 Likes
11

^ Solution.

$ JULIA_DEBUG=mymodule julia myfile.jl 
┌ Debug: thanks, Sukera
└ @ Main.mymodule ~/dwave_project/myfile.jl:3

with myfile.jl like

using Logging
module mymodule
@debug "thanks, Sukera"
end
1 Like