Make it possible to format the output in DatetimeRotatingLogger

by using FormatLogger as a backend.

Author: fredrikekre

README.md

@@ -316,6 +316,8 @@ julia> filter(f -> endswith(f, ".log"), readdir(pwd()))
 ```
 
 The user implicitly controls when the files will be rolled over based on the `DateFormat` given.
+To control the logging output it is possible to pass a formatter function as the first argument
+in the constructor. See `FormatLogger` for the requirements on the formatter function.
 
 ## `FormatLogger` (*Sink*)
 The `FormatLogger` is a sink that formats the message and prints to a wrapped IO.

src/LoggingExtras.jl

@@ -38,8 +38,8 @@ include("activefiltered.jl")
 include("earlyfiltered.jl")
 include("minlevelfiltered.jl")
 include("filelogger.jl")
-include("datetime_rotation.jl")
 include("formatlogger.jl")
+include("datetime_rotation.jl")
 include("deprecated.jl")
 
 end # module

src/datetime_rotation.jl

@@ -2,39 +2,64 @@ using Dates
 import Base: isless
 
 raw"""
-    DatetimeRotatingFileLogger
+    DatetimeRotatingFileLogger(dir, file_pattern; always_flush=true)
+    DatetimeRotatingFileLogger(f::Function, dir, file_pattern; always_flush=true)
 
-Constructs a FileLogger that rotates its file based on the current date.
+Construct a `DatetimeRotatingFileLogger` that rotates its file based on the current date.
+The constructor takes a log output directory, `dir`, and a filename pattern.
 The filename pattern given is interpreted through the `Dates.format()` string formatter,
 allowing for yearly all the way down to millisecond-level log rotation.  Note that if you
 wish to have a filename portion that is not interpreted as a format string, you may need
-to escape portions of the filename, as shown below:
+to escape portions of the filename, as shown in the example below.
 
-Usage example:
+It is possible to pass a formatter function as the first argument to control the output.
+The formatting function should be of the form `f(io::IOContext, log_args::NamedTuple)`
+where `log_args` has the following fields:
+`(level, message, _module, group, id, file, line, kwargs)`.
+See `?LoggingExtra.handle_message_args` for more information about what each field represents.
 
-    logger = DatetimeRotatingFileLogger(log_dir, raw"\a\c\c\e\s\s-YYYY-mm-dd.\l\o\g")
+# Examples
+
+```julia
+# Logger that logs to a new file every day
+logger = DatetimeRotatingFileLogger(log_dir, raw"\a\c\c\e\s\s-yyyy-mm-dd.\l\o\g")
+
+# Logger with a formatter function that rotates the log file hourly
+logger = DatetimeRotatingFileLogger(log_dir, raw"yyyy-mm-dd-HH.\l\o\g") do io, args
+    println(io, args.level, " | ", args.message)
+end
 """
 mutable struct DatetimeRotatingFileLogger <: AbstractLogger
-    logger::SimpleLogger
+    logger::Union{SimpleLogger,FormatLogger}
     dir::String
     filename_pattern::DateFormat
     next_reopen_check::DateTime
     always_flush::Bool
 end
 
 function DatetimeRotatingFileLogger(dir, filename_pattern; always_flush=true)
-    format = DateFormat(filename_pattern)
-    return DatetimeRotatingFileLogger(
-        SimpleLogger(open(calc_logpath(dir, filename_pattern), "a"), BelowMinLevel),
-        dir,
-        format,
-        next_datetime_transition(format),
-        always_flush,
-    )
+    DatetimeRotatingFileLogger(nothing, dir, filename_pattern; always_flush=always_flush)
+end
+function DatetimeRotatingFileLogger(f::Union{Function,Nothing}, dir, filename_pattern; always_flush=true)
+    # Construct the backing logger with a temp IOBuffer that will be replaced
+    # by the correct filestream in the call to reopen! below
+    logger = if f === nothing
+        SimpleLogger(IOBuffer(), BelowMinLevel)
+    else # f isa Function
+        FormatLogger(f, IOBuffer(); always_flush=false) # no need to flush twice
+    end
+    # abspath in case user constructs the logger with a relative path and later cd's.
+    drfl = DatetimeRotatingFileLogger(logger, abspath(dir),
+        DateFormat(filename_pattern), now(), always_flush)
+    reopen!(drfl)
+    return drfl
 end
 
+similar_logger(::SimpleLogger, io) = SimpleLogger(io, BelowMinLevel)
+similar_logger(l::FormatLogger, io) = FormatLogger(l.f, io, l.always_flush)
 function reopen!(drfl::DatetimeRotatingFileLogger)
-    drfl.logger = SimpleLogger(open(calc_logpath(drfl.dir, drfl.filename_pattern), "a"), BelowMinLevel)
+    io = open(calc_logpath(drfl.dir, drfl.filename_pattern), "a")
+    drfl.logger = similar_logger(drfl.logger, io)
     drfl.next_reopen_check = next_datetime_transition(drfl.filename_pattern)
     return nothing
 end

src/formatlogger.jl

@@ -1,7 +1,7 @@
 
 struct FormatLogger <: AbstractLogger
     f::Function
-    io::IO
+    stream::IO
     always_flush::Bool
 end
 
@@ -39,10 +39,10 @@ function handle_message(logger::FormatLogger, args...; kwargs...)
     # We help the user by passing an IOBuffer to the formatting function
     # to make sure that everything writes to the logger io in one go.
     iob = IOBuffer()
-    ioc = IOContext(iob, logger.io)
+    ioc = IOContext(iob, logger.stream)
     logger.f(ioc, log_args)
-    write(logger.io, take!(iob))
-    logger.always_flush && flush(logger.io)
+    write(logger.stream, take!(iob))
+    logger.always_flush && flush(logger.stream)
     return nothing
 end
 shouldlog(logger::FormatLogger, arg...) = true

test/runtests.jl

@@ -126,7 +126,10 @@ end
     mktempdir() do dir
         drfl_sec = DatetimeRotatingFileLogger(dir, raw"\s\e\c-YYYY-mm-dd-HH-MM-SS.\l\o\g")
         drfl_min = DatetimeRotatingFileLogger(dir, raw"\m\i\n-YYYY-mm-dd-HH-MM.\l\o\g")
-        sink = TeeLogger(drfl_sec, drfl_min)
+        func = (io, args) -> println(io, reverse(args.message))
+        drfl_fmt = DatetimeRotatingFileLogger(func, dir, raw"\f\m\t-YYYY-mm-dd-HH-MM-SS.\l\o\g")
+
+        sink = TeeLogger(drfl_sec, drfl_min, drfl_fmt)
         with_logger(sink) do
             while millisecond(now()) < 100 || millisecond(now()) > 200
                 sleep(0.001)
@@ -146,6 +149,9 @@ end
         min_files = filter(f -> startswith(basename(f), "min-"), files)
         @test length(min_files) == 1
 
+        fmt_files = filter(f -> startswith(basename(f), "fmt-"), files)
+        @test length(fmt_files) == 2
+
         sec1_data = String(read(sec_files[1]))
         @test occursin("first", sec1_data)
         @test occursin("second", sec1_data)
@@ -156,6 +162,12 @@ end
         @test occursin("first", min_data)
         @test occursin("second", min_data)
         @test occursin("third", min_data)
+
+        fmt_data = String(read(fmt_files[1]))
+        @test occursin("tsrif", fmt_data)
+        @test occursin("dnoces", fmt_data)
+        fmt_data = String(read(fmt_files[2]))
+        @test occursin("driht", fmt_data)
     end
 end
 
@@ -186,7 +198,7 @@ end
     @test logger.always_flush
     # Test constructor with default io and kwarg
     logger = FormatLogger(x -> x; always_flush=false)
-    @test logger.io === stderr
+    @test logger.stream === stderr
     @test !logger.always_flush
 end