Logging

TheLogging module provides a way to record the history and progress of a computation as a log of events. Events are created by inserting a logging statement into the source code, for example:

@warn "Abandon printf debugging, all ye who enter here!"┌ Warning: Abandon printf debugging, all ye who enter here!└ @ Main REPL[1]:1

The system provides several advantages over peppering your source code with calls toprintln(). First, it allows you to control the visibility and presentation of messages without editing the source code. For example, in contrast to the@warn above

@debug "The sum of some values $(sum(rand(100)))"

will produce no output by default. Furthermore, it's very cheap to leave debug statements like this in the source code because the system avoids evaluating the message if it would later be ignored. In this casesum(rand(100)) and the associated string processing will never be executed unless debug logging is enabled.

Second, the logging tools allow you to attach arbitrary data to each event as a set of key–value pairs. This allows you to capture local variables and other program state for later analysis. For example, to attach the local array variableA and the sum of a vectorv as the keys you can use

A = ones(Int, 4, 4)v = ones(100)@info "Some variables"  A  s=sum(v)# output┌ Info: Some variables│   A =│    4×4 Matrix{Int64}:│     1  1  1  1│     1  1  1  1│     1  1  1  1│     1  1  1  1└   s = 100.0

All of the logging macros@debug,@info,@warn and@error share common features that are described in detail in the documentation for the more general macro@logmsg.

Log event structure

Each event generates several pieces of data, some provided by the user and some automatically extracted. Let's examine the user-defined data first:

• Thelog level is a broad category for the message that is used for early filtering. There are several standard levels of typeLogLevel; user-defined levels are also possible. Each is distinct in purpose:

  • Logging.Debug (log level -1000) is information intended for the developer of the program. These events are disabled by default.
  • Logging.Info (log level 0) is for general information to the user. Think of it as an alternative to usingprintln directly.
  • Logging.Warn (log level 1000) means something is wrong and action is likely required but that for now the program is still working.
  • Logging.Error (log level 2000) means something is wrong and it is unlikely to be recovered, at least by this part of the code. Often this log-level is unneeded as throwing an exception can convey all the required information.

• Themessage is an object describing the event. By conventionAbstractStrings passed as messages are assumed to be in markdown format. Other types will be displayed usingprint(io, obj) orstring(obj) for text-based output and possiblyshow(io,mime,obj) for other multimedia displays used in the installed logger.

• Optionalkey–value pairs allow arbitrary data to be attached to each event. Some keys have conventional meaning that can affect the way an event is interpreted (see@logmsg).

The system also generates some standard information for each event:

• Themodule in which the logging macro was expanded.
• Thefile andline where the logging macro occurs in the source code.
• A messageid that is a unique, fixed identifier for thesource code statement where the logging macro appears. This identifier is designed to be fairly stable even if the source code of the file changes, as long as the logging statement itself remains the same.
• Agroup for the event, which is set to the base name of the file by default, without extension. This can be used to group messages into categories more finely than the log level (for example, all deprecation warnings have group:depwarn), or into logical groupings across or within modules.

Notice that some useful information such as the event time is not included by default. This is because such information can be expensive to extract and is alsodynamically available to the current logger. It's simple to define acustom logger to augment event data with the time, backtrace, values of global variables and other useful information as required.

Processing log events

As you can see in the examples, logging statements make no mention of where log events go or how they are processed. This is a key design feature that makes the system composable and natural for concurrent use. It does this by separating two different concerns:

• Creating log events is the concern of the module author who needs to decide where events are triggered and which information to include.
• Processing of log events — that is, display, filtering, aggregation and recording — is the concern of the application author who needs to bring multiple modules together into a cooperating application.

Loggers

Processing of events is performed by alogger, which is the first piece of user configurable code to see the event. All loggers must be subtypes ofAbstractLogger.

When an event is triggered, the appropriate logger is found by looking for a task-local logger with the global logger as fallback. The idea here is that the application code knows how log events should be processed and exists somewhere at the top of the call stack. So we should look up through the call stack to discover the logger — that is, the logger should bedynamically scoped. (This is a point of contrast with logging frameworks where the logger islexically scoped; provided explicitly by the module author or as a simple global variable. In such a system it's awkward to control logging while composing functionality from multiple modules.)

The global logger may be set withglobal_logger, and task-local loggers controlled usingwith_logger. Newly spawned tasks inherit the logger of the parent task.

There are three logger types provided by the library.ConsoleLogger is the default logger you see when starting the REPL. It displays events in a readable text format and tries to give simple but user friendly control over formatting and filtering.NullLogger is a convenient way to drop all messages where necessary; it is the logging equivalent of thedevnull stream.SimpleLogger is a very simplistic text formatting logger, mainly useful for debugging the logging system itself.

Custom loggers should come with overloads for the functions described in thereference section.

Early filtering and message handling

When an event occurs, a few steps of early filtering occur to avoid generating messages that will be discarded:

1. The message log level is checked against a global minimum level (set viadisable_logging). This is a crude but extremely cheap global setting.
2. The current logger state is looked up and the message level checked against the logger's cached minimum level, as found by callingLogging.min_enabled_level. This behavior can be overridden via environment variables (more on this later).
3. TheLogging.shouldlog function is called with the current logger, taking some minimal information (level, module, group, id) which can be computed statically. Most usefully,shouldlog is passed an eventid which can be used to discard events early based on a cached predicate.

If all these checks pass, the message and key–value pairs are evaluated in full and passed to the current logger via theLogging.handle_message function.handle_message() may perform additional filtering as required and display the event to the screen, save it to a file, etc.

Exceptions that occur while generating the log event are captured and logged by default. This prevents individual broken events from crashing the application, which is helpful when enabling little-used debug events in a production system. This behavior can be customized per logger type by extendingLogging.catch_exceptions.

Testing log events

Log events are a side effect of running normal code, but you might find yourself wanting to test particular informational messages and warnings. TheTest module provides a@test_logs macro that can be used to pattern match against the log event stream.

Environment variables

Message filtering can be influenced through theJULIA_DEBUG environment variable, and serves as an easy way to enable debug logging for a file or module. Loading julia withJULIA_DEBUG=loading will activate@debug log messages inloading.jl. For example, in Linux shells:

$ JULIA_DEBUG=loading julia -e 'using OhMyREPL'┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji due to it containing an incompatible cache header└ @ Base loading.jl:1328[ Info: Recompiling stale cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji for module OhMyREPL┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/Tokenize.ji due to it containing an incompatible cache header└ @ Base loading.jl:1328...

On windows, the same can be achieved inCMD via first runningset JULIA_DEBUG="loading" and inPowershell via$env:JULIA_DEBUG="loading".

Similarly, the environment variable can be used to enable debug logging of modules, such asPkg, or module roots (seeBase.moduleroot). To enable all debug logging, use the special valueall.

To turn debug logging on from the REPL, setENV["JULIA_DEBUG"] to the name of the module of interest. Functions defined in the REPL belong to moduleMain; logging for them can be enabled like this:

julia> foo() = @debug "foo"foo (generic function with 1 method)julia> foo()julia> ENV["JULIA_DEBUG"] = MainMainjulia> foo()┌ Debug: foo└ @ Main REPL[1]:1

Use a comma separator to enable debug for multiple modules:JULIA_DEBUG=loading,Main.

Examples

Example: Writing log events to a file

Sometimes it can be useful to write log events to a file. Here is an example of how to use a task-local and global logger to write information to a text file:

# Load the logging modulejulia> using Logging# Open a textfile for writingjulia> io = open("log.txt", "w+")IOStream(<file log.txt>)# Create a simple loggerjulia> logger = SimpleLogger(io)SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())# Log a task-specific messagejulia> with_logger(logger) do           @info("a context specific log message")       end# Write all buffered messages to the filejulia> flush(io)# Set the global logger to loggerjulia> global_logger(logger)SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())# This message will now also be written to the filejulia> @info("a global log message")# Close the filejulia> close(io)

Example: Enable debug-level messages

Here is an example of creating aConsoleLogger that lets through any messages with log level higher than, or equal, toLogging.Debug.

julia> using Logging# Create a ConsoleLogger that prints any log messages with level >= Debug to stderrjulia> debuglogger = ConsoleLogger(stderr, Logging.Debug)# Enable debuglogger for a taskjulia> with_logger(debuglogger) do           @debug "a context specific log message"       end# Set the global loggerjulia> global_logger(debuglogger)

Reference

Logging module

Creating events

@debug message  [key=value | value ...]@info  message  [key=value | value ...]@warn  message  [key=value | value ...]@error message  [key=value | value ...]@logmsg level message [key=value | value ...]

@debug "Verbose debugging information.  Invisible by default"@info  "An informational message"@warn  "Something was odd.  You should pay attention"@error "A non fatal error occurred"x = 10@info "Some variables attached to the message" x a=42.0@debug begin    sA = sum(A)    "sum(A) = $sA is an expensive operation, evaluated only when `shouldlog` returns true"endfor i=1:10000    @info "With the default backend, you will only see (i = $i) ten times"  maxlog=10    @debug "Algorithm1" i progress=i/10000end

LogLevel(level)

julia> Logging.LogLevel(0) == Logging.Infotrue

Debug

Info

Warn

Error

BelowMinLevel

AboveMaxLevel

Processing events with AbstractLogger

Event processing is controlled by overriding functions associated withAbstractLogger:

handle_message(logger, level, message, _module, group, id, file, line; key1=val1, ...)

shouldlog(logger, level, _module, group, id)

min_enabled_level(logger)

catch_exceptions(logger)

disable_logging(level)

Logging.disable_logging(Logging.Info) # Disable debug and info

Using Loggers

Logger installation and inspection:

global_logger()

global_logger(logger)

with_logger(function, logger)

function test(x)    @info "x = $x"endwith_logger(logger) do    test(1)    test([1,2])end

current_logger()

Loggers that are supplied with the system:

NullLogger()

ConsoleLogger([stream,] min_level=Info; meta_formatter=default_metafmt,              show_limited=true, right_justify=0)

SimpleLogger([stream,] min_level=Info)