Threadsafe TerminalLogger (#41)

Added a big lock around TerminalLogger state to make it safe to use
from multiple threads.

Also
* Bump version
* Fix tests which are now broken on julia 1.6 due to formatting detail
  of Matrix.
* Update CI to run on more recent Julia versions

.github/workflows/ci.yml

@@ -13,7 +13,9 @@ jobs:
       matrix:
         version:
           - '1.0'
-          - '1.3'
+          - '1.6'
+          - '1'
+          - 'nightly'
         os:
           - ubuntu-latest
           - macOS-latest

Project.toml

@@ -1,7 +1,7 @@
 name = "TerminalLoggers"
 uuid = "5d786b92-1e48-4d6f-9151-6b4477ca9bed"
 authors = ["Chris Foster <[email protected]>"]
-version = "0.1.4"
+version = "0.1.5"
 
 [deps]
 LeftChildRightSiblingTrees = "1d6d02ad-be62-4b6b-8a6d-2f90e265016e"

src/TerminalLogger.jl

@@ -34,6 +34,7 @@ struct TerminalLogger <: AbstractLogger
     message_limits::Dict{Any,Int}
     sticky_messages::StickyMessages
     bartrees::Vector{Node{ProgressBar}}
+    lock::ReentrantLock
 end
 function TerminalLogger(stream::IO=stderr, min_level=ProgressLevel;
                         meta_formatter=default_metafmt, show_limited=true,
@@ -49,11 +50,15 @@ function TerminalLogger(stream::IO=stderr, min_level=ProgressLevel;
         Dict{Any,Int}(),
         StickyMessages(stream),
         Union{}[],
+        ReentrantLock()
     )
 end
 
-shouldlog(logger::TerminalLogger, level, _module, group, id) =
-    get(logger.message_limits, id, 1) > 0
+function shouldlog(logger::TerminalLogger, level, _module, group, id)
+    lock(logger.lock) do
+        get(logger.message_limits, id, 1) > 0
+    end
+end
 
 min_enabled_level(logger::TerminalLogger) = logger.min_level
 
@@ -280,14 +285,19 @@ function handle_message(logger::TerminalLogger, level, message, _module, group,
                         filepath, line; maxlog=nothing,
                         sticky=nothing, kwargs...)
     if maxlog !== nothing && maxlog isa Integer
-        remaining = get!(logger.message_limits, id, maxlog)
-        logger.message_limits[id] = remaining - 1
+        remaining = 0
+        lock(logger.lock) do
+            remaining = get!(logger.message_limits, id, maxlog)
+            logger.message_limits[id] = remaining - 1
+        end
         remaining > 0 || return
     end
 
     progress = asprogress(level, message, _module, group, id, filepath, line; kwargs...)
     if progress !== nothing
-        handle_progress(logger, progress, kwargs)
+        lock(logger.lock) do
+            handle_progress(logger, progress, kwargs)
+        end
         return
     end
 
@@ -343,18 +353,21 @@ function handle_message(logger::TerminalLogger, level, message, _module, group,
     end
 
     msg = take!(buf)
-    if sticky !== nothing
-        # Ensure we see the last message, even if it's :done
-        push!(logger.sticky_messages, id=>String(msg))
-        if sticky == :done
-            pop!(logger.sticky_messages, id)
+
+    lock(logger.lock) do
+        if sticky !== nothing
+            # Ensure we see the last message, even if it's :done
+            push!(logger.sticky_messages, id=>String(msg))
+            if sticky == :done
+                pop!(logger.sticky_messages, id)
+            end
+        else
+            write(logger.stream, msg)
+        end
+
+        if logger.always_flush
+            flush(logger.stream)
         end
-    else
-        write(logger.stream, msg)
-    end
-
-    if logger.always_flush
-        flush(logger.stream)
     end
 
     nothing

test/TerminalLogger.jl

@@ -1,5 +1,7 @@
 using TerminalLoggers: default_metafmt, format_message
 
+using ProgressLogging
+
 @noinline func1() = backtrace()
 
 function dummy_metafmt(level, _module, group, id, file, line)
@@ -192,8 +194,8 @@ end
     ┌ PREFIX msg
     │   exception =
     │    DivideError: integer division error
-    │    Stacktrace:
-    │     [1] func1() at""")
+    │    Stacktrace:""")
+    @test occursin("[1] func1", genmsg("msg", exception=(DivideError(),bt)))
 
     # Exception stacks
     if VERSION >= v"1.2"
@@ -211,19 +213,21 @@ end
     end
 
     @testset "Limiting large data structures" begin
-        @test genmsg("msg", a=fill(1.00001, 100,100), b=fill(2.00002, 10,10)) ==
+        a = fill(1.00001, 10,10)
+        b = fill(2.00002, 10,10)
+        @test genmsg("msg", a=a, b=b) ==
         replace("""
         ┌ PREFIX msg
         │   a =
-        │    100×100 Array{Float64,2}:
+        │    $(summary(a)):
         │     1.00001  1.00001  1.00001  1.00001  …  1.00001  1.00001  1.00001
         │     1.00001  1.00001  1.00001  1.00001     1.00001  1.00001  1.00001
         │     1.00001  1.00001  1.00001  1.00001     1.00001  1.00001  1.00001
         │     ⋮                                   ⋱                           EOL
         │     1.00001  1.00001  1.00001  1.00001     1.00001  1.00001  1.00001
         │     1.00001  1.00001  1.00001  1.00001     1.00001  1.00001  1.00001
         │   b =
-        │    10×10 Array{Float64,2}:
+        │    $(summary(b)):
         │     2.00002  2.00002  2.00002  2.00002  …  2.00002  2.00002  2.00002
         │     2.00002  2.00002  2.00002  2.00002     2.00002  2.00002  2.00002
         │     2.00002  2.00002  2.00002  2.00002     2.00002  2.00002  2.00002
@@ -237,11 +241,11 @@ end
         (VERSION < v"1.4-" ? "EOL" : "       EOL")=>""
         )
         # Limiting the amount which is printed
-        @test genmsg("msg", a=fill(1.00001, 10,10), show_limited=false) ==
+        @test genmsg("msg", a=a, show_limited=false) ==
         """
         ┌ PREFIX msg
         │   a =
-        │    10×10 Array{Float64,2}:
+        │    $(summary(a)):
         │     1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001
         │     1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001
         │     1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001  1.00001
@@ -300,9 +304,8 @@ end
 
         # For non-strings a blank line is added so that any formatting for
         # vertical alignment isn't broken
-        @test format_message([1 2; 3 4], 6, io_ctx) ==
+        @test format_message(Text(" 1  2\n 3  4"), 6, io_ctx) ==
             ["",
-             "2×2 Array{Int64,2}:",
              " 1  2",
              " 3  4"]
     end
@@ -393,4 +396,40 @@ end
         Outer 100%\|█+\| Time: .*
         """
     end
+
+    @static if VERSION >= v"1.3.0"
+        @testset "Parallel progress" begin
+            buf = IOBuffer()
+            io = IOContext(buf, :displaysize=>(30,75), :color=>false)
+            logger = TerminalLogger(io, Debug)
+            # Crude multithreading test: generate some contention.
+            #
+            # Generate some contention in multi-threaded cases
+            ntasks = 8
+            @sync begin
+                with_logger(logger) do
+                    for i=1:ntasks
+                        Threads.@spawn for j=1:100
+                            @info "XXXX <$i,$j>" maxlog=100
+                            #sleep(0.001)
+                        end
+                    end
+                end
+            end
+            log_str = String(take!(buf))
+            @test length(findall("XXXX", log_str)) == 100
+
+            # Fun test of parallel progress logging to watch interactively:
+            #=
+            using ProgressLogging
+            @sync begin
+                for i=1:8
+                    Threads.@spawn @progress name="task $i" threshold=0.00005 for j=1:10000
+                        #sleep(0.001)
+                    end
+                end
+            end
+            =#
+        end
+    end
 end

test/runtests.jl

@@ -3,7 +3,8 @@ using Test
 
 using Logging:
     LogLevel, BelowMinLevel, Debug, Info, Warn, Error, AboveMaxLevel,
-    shouldlog, handle_message, min_enabled_level, catch_exceptions
+    shouldlog, handle_message, min_enabled_level, catch_exceptions,
+    with_logger
 
 using ProgressLogging: Progress
 using UUIDs: UUID