Filtering log messages in a big Julia package

Filtering log messages in a big Julia package.ipynb

Filtering log messages in a big Julia package.jl

# -*- coding: utf-8 -*-
# ---
# jupyter:
#   jupytext:
#     formats: jl:light,ipynb
#     text_representation:
#       extension: .jl
#       format_name: light
#       format_version: '1.5'
#       jupytext_version: 1.7.1
#   kernelspec:
#     display_name: Julia 1.6.1
#     language: julia
#     name: julia-1.6
# ---

# # Filtering log messages in a big package

# When debugging a package, it's often useful to add plenty of
# [`@debug`](https://docs.julialang.org/en/v1/stdlib/Logging/#Logging) log
# statements to check which code paths are running and inspect values --
# especially since GUI integrations with Julia's interactive debugger are not
# yet very usable (as compared to, e.g.,
# [PyCharm](https://www.jetbrains.com/pycharm/features/debugger.html)/`pdb`
# integration which has heavy industry support).
#
# A key feature of `@debug` messages is that they can be left in the codebase,
# since they are disabled by default.  However, after doing this for a while, I
# found that every time I wanted to debug something, I had to comb through the
# 99+% log messages in code paths other than the one I wanted to inspect.
# Furthermore, this massive output was printed the terminal or Jupyter cell
# output, both of which are hard to scroll through and easy to lose.

# To address these problems, I've been using two simple / lightweight solutions:

# ## Sending logs to a timestamped file

# The first and probably most general solution is to send all log messages to a
# timestamped file.  Timestamped so that it won't get clobbered on next run,
# and file so that it can be browsed and processed with a more powerful text
# viewer or editor.  (Luckily I haven't yet gotten to the point where my logs
# are prohibitively large to open in an editor, but I'll probably get there and
# need to stick with a lazy-loading pager like `less`.)

# +
import Logging as L
import Logging: LogLevel, @logmsg
import Dates
unix_now() = round(Int, Dates.datetime2unix(Dates.now()))

ENV["JULIA_DEBUG"] = Main
logfile_path = abspath("logs/testrun_log_$(unix_now())")
@info "Log output from here on will go to $logfile_path"
open(logfile_path, "w") do logfile_io
L.with_logger(L.SimpleLogger(logfile_io)) do
        
x = 1 + 2
@debug "Here's what I think one plus two is:" x

end  # with_logger
end  # open(logfile_path, "w")
# -

# This produces a log file with contents:

println(read(logfile_path, String))

# which is quite a lot of information to take in.  I can browse the file
# carefully, and send it to colleagues to help me understand what's going on.

# ## Creating and filtering for a new log level

# The built-in logger classes in Julia are pretty minimal, but as the
# [docs](https://docs.julialang.org/en/v1/stdlib/Logging/) explain, it's easy
# to create a custom logger.  One custom logger I've found to be very useful is
# a wrapper around an existing logger (e.g., the default logger) that filters
# for one specific log level.  That, along with creating a new log level when
# I'm debugging a new code path, makes it possible to keep the log printout
# short and focus my attention on the log messages I want to see.

# +
struct LevelRangeLogger <: L.AbstractLogger
    inner_logger::L.AbstractLogger
    min_level::L.LogLevel
    max_level::L.LogLevel
end

function L.handle_message(logger::LevelRangeLogger, level, message,
                          _module, group, id, file, line; kwargs...)
    L.handle_message(logger.inner_logger, level, message, _module,
                     group, id, file, line; kwargs...)
end

function L.min_enabled_level(logger::LevelRangeLogger)
    return L.min_enabled_level(logger.inner_logger)
end

function L.shouldlog(logger::LevelRangeLogger, level, _module, group, id)
    return (logger.min_level ≤ level
            && level ≤ logger.max_level
            && L.shouldlog(logger.inner_logger, level, _module, group, id))
end

function one_level_logger(inner_logger::L.AbstractLogger,
                          level::L.LogLevel)
    return LevelRangeLogger(inner_logger, level, level)
end

with_only_loglevel(f, level::L.LogLevel) = L.with_logger(
    f, one_level_logger(L.global_logger(), level))
;
# -

# Then in my application code:

# +
module MyApplication

import Logging: LogLevel, @logmsg

LOG_MULTIPLICATION = LogLevel(-950)

function crunch_numbers()
    x = 1 + 2
    @debug "Addition results" x
    y = 1 * 2
    @logmsg LOG_MULTIPLICATION "multiplication results" y
end

end  # module MyApplication
;
# -

# And when running the application (e.g. in a REPL or notebook):

# +
ENV["JULIA_DEBUG"] = "Main,MyApplication"

with_only_loglevel(MyApplication.LOG_MULTIPLICATION) do
    MyApplication.crunch_numbers()
end
# -

# If I only have a few user-defined log levels as above, it would be fairly
# straightforward to redefine
# [`Base.show(::LogLevel)`](https://github.com/JuliaLang/julia/blob/ae8452a9e0b973991c30f27beb2201db1b0ea0d3/base/logging.jl#L142-L151)
# to produce custom display text for them, so that the printout looks like
#
# ```
# ┌ LogMultiplication: multiplication results
# │   y = 2
# └ @ Main.MyApplication In[8]:11
# ```
#
# However, doing this systematically (and, e.g., handling name conflicts) would
# be more complicated than it's worth in my opinion, and would also add
# performance cost to a fairly performance-critical part of Julia's core
# functionality.  So I've stayed away from that.