Thread- and process-id in log messages?

General Usage
1

It would be very useful to have a mechanism that automatically adds thread- and process-id to log messages. Can this currently be implemented using a custom logger, or would this require changes to Julia’s logging system?

1 Like
2

Can you not just
@info Threads.threeadid()

I guess you want to have the threadid automatically inserted?

3

Yes, this should be transparent to the user, if possible. For once, for convenience, but also so that logging in third-party code will also be annotated with thread/process information automatically.

For now, I’m doing this by hand, but it’s been extremely valuable for debugging multi-threaded and/or distributed code.

4

Ok, turns out a custom logger can do this just fine - at least on Julia v1.2 and 1.3, handle_message() is called on the same thread as the logging call, so handle_message() can just use threadid(). Worker info is added automatically as part of the print command(s):

# Requires Julia >= v1.2 (and ParallelProcessingTools.jl >= v0.4)

using Distributed
addprocs(2)

@everywhere begin

using Base.CoreLogging: AbstractLogger, LogLevel, Info, Debug, Warn, Error, global_logger
import Base.CoreLogging: shouldlog, min_enabled_level, handle_message

using Base.Threads: threadid
using Distributed: myid


# Mostly a copy of Base.CoreLogging.SimpleLogger, only
# `" (thread $(threadid())): "` has been added:

struct ProcThreadInfoLogger <: AbstractLogger
    stream::IO
    min_level::LogLevel
    message_limits::Dict{Any,Int}
end
ProcThreadInfoLogger(stream::IO=stderr, level=Info) = ProcThreadInfoLogger(stream, level, Dict{Any,Int}())

shouldlog(logger::ProcThreadInfoLogger, level, _module, group, id) =
    get(logger.message_limits, id, 1) > 0

min_enabled_level(logger::ProcThreadInfoLogger) = logger.min_level

catch_exceptions(logger::ProcThreadInfoLogger) = false

function handle_message(logger::ProcThreadInfoLogger, level, message, _module, group, id,
                        filepath, line; maxlog=nothing, kwargs...)
    if maxlog !== nothing && maxlog isa Integer
        remaining = get!(logger.message_limits, id, maxlog)
        logger.message_limits[id] = remaining - 1
        remaining > 0 || return
    end
    buf = IOBuffer()
    iob = IOContext(buf, logger.stream)
    levelstr = level == Warn ? "Warning" : string(level)
    msglines = split(chomp(string(message)), '\n')
    println(iob, "┌ ", levelstr, " (thread $(threadid())): ", msglines[1])
    for i in 2:length(msglines)
        println(iob, "│ ", msglines[i])
    end
    for (key, val) in kwargs
        println(iob, "│   ", key, " = ", val)
    end
    println(iob, "└ @ ", something(_module, "nothing"), " ",
            something(filepath, "nothing"), ":", something(line, "nothing"))
    write(logger.stream, take!(buf))
    nothing
end


end # @everywhere


# Activate:

@everywhere global_logger(ProcThreadInfoLogger(stderr, Debug))


# Test:

@debug "foo"

@everywhere using ParallelProcessingTools
@onprocs procs() @onthreads allthreads() @info 42 threadid()
1 Like