Merge pull request #42 from fredrikekre/fe/callback

Implement a callback function for DatetimeRotatingFileLogger.

Author: oxinabox

README.md

@@ -316,6 +316,9 @@ 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 post-process the newly rotated file pass `rotation_callback::Function` as a keyword argument.
+See the docstring with (`?DatetimeRotatingFileLogger` in the REPL) for more details.
+
 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.
 

src/datetime_rotation.jl

@@ -2,13 +2,13 @@ using Dates
 import Base: isless
 
 raw"""
-    DatetimeRotatingFileLogger(dir, file_pattern; always_flush=true)
-    DatetimeRotatingFileLogger(f::Function, dir, file_pattern; always_flush=true)
+    DatetimeRotatingFileLogger(dir, file_pattern; always_flush=true, rotation_callback=identity)
+    DatetimeRotatingFileLogger(f::Function, dir, file_pattern; always_flush=true, rotation_callback=identity)
 
 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
+allowing for yearly all the way down to minute-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 in the example below.
 
@@ -18,6 +18,11 @@ 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.
 
+It is also possible to pass `rotation_callback::Function` as a keyword argument. This function
+will be called every time a file rotation is happening. The function should accept one
+argument which is the absolute path to the just-rotated file. The logger will block until
+the callback function returns. Use `@async` if the callback is expensive.
+
 # Examples
 
 ```julia
@@ -28,19 +33,27 @@ logger = DatetimeRotatingFileLogger(log_dir, raw"\a\c\c\e\s\s-yyyy-mm-dd.\l\o\g"
 logger = DatetimeRotatingFileLogger(log_dir, raw"yyyy-mm-dd-HH.\l\o\g") do io, args
     println(io, args.level, " | ", args.message)
 end
+
+# Example callback function to compress the recently-closed file
+compressor(file) = run(`gzip $(file)`)
+logger = DatetimeRotatingFileLogger(...; rotation_callback=compressor)
+```
 """
 mutable struct DatetimeRotatingFileLogger <: AbstractLogger
     logger::Union{SimpleLogger,FormatLogger}
     dir::String
     filename_pattern::DateFormat
     next_reopen_check::DateTime
     always_flush::Bool
+    reopen_lock::ReentrantLock
+    current_file::Union{String,Nothing}
+    rotation_callback::Function
 end
 
-function DatetimeRotatingFileLogger(dir, filename_pattern; always_flush=true)
-    DatetimeRotatingFileLogger(nothing, dir, filename_pattern; always_flush=always_flush)
+function DatetimeRotatingFileLogger(dir, filename_pattern; always_flush=true, rotation_callback=identity)
+    DatetimeRotatingFileLogger(nothing, dir, filename_pattern; always_flush=always_flush, rotation_callback=rotation_callback)
 end
-function DatetimeRotatingFileLogger(f::Union{Function,Nothing}, dir, filename_pattern; always_flush=true)
+function DatetimeRotatingFileLogger(f::Union{Function,Nothing}, dir, filename_pattern; always_flush=true, rotation_callback=identity)
     # 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
@@ -50,15 +63,22 @@ function DatetimeRotatingFileLogger(f::Union{Function,Nothing}, dir, filename_pa
     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)
+        DateFormat(filename_pattern), now(), always_flush, ReentrantLock(), nothing, rotation_callback)
     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)
-    io = open(calc_logpath(drfl.dir, drfl.filename_pattern), "a")
+    if drfl.current_file !== nothing
+        # close the old IOStream and pass the file to the callback
+        close(drfl.logger.stream)
+        drfl.rotation_callback(drfl.current_file)
+    end
+    new_file = calc_logpath(drfl.dir, drfl.filename_pattern)
+    drfl.current_file = new_file
+    io = open(new_file, "a")
     drfl.logger = similar_logger(drfl.logger, io)
     drfl.next_reopen_check = next_datetime_transition(drfl.filename_pattern)
     return nothing
@@ -104,15 +124,19 @@ function next_datetime_transition(fmt::DateFormat)
 
     tokens = filter(t -> isa(t, Dates.DatePart), collect(fmt.tokens))
     minimum_timescale = first(sort(map(t -> token_timescales[extract_token(t)], tokens), lt=custom_isless))
-    return ceil(now(), minimum_timescale) - Second(1)
+    if minimum_timescale < Minute(1)
+        throw(ArgumentError("rotating the logger with sub-minute resolution not supported"))
+    end
+    return ceil(now(), minimum_timescale)
 end
 
 calc_logpath(dir, filename_pattern) = joinpath(dir, Dates.format(now(), filename_pattern))
 
 function handle_message(drfl::DatetimeRotatingFileLogger, args...; kwargs...)
-    if now() >= drfl.next_reopen_check
-        flush(drfl.logger.stream)
-        reopen!(drfl)
+    lock(drfl.reopen_lock) do
+        if now() >= drfl.next_reopen_check
+            reopen!(drfl)
+        end
     end
     handle_message(drfl.logger, args...; kwargs...)
     drfl.always_flush && flush(drfl.logger.stream)

test/runtests.jl

@@ -124,41 +124,52 @@ end
 
 @testset "DatetimeRotatingFileLogger" begin
     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")
+        drfl_hour = DatetimeRotatingFileLogger(dir, raw"\h\o\u\r-YYYY-mm-dd-HH.\l\o\g")
         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")
+        drfl_fmt = DatetimeRotatingFileLogger(func, dir, raw"\f\m\t-YYYY-mm-dd-HH-MM.\l\o\g")
+        callback_record = []
+        callback(f) = filesize(f) > 0 && push!(callback_record, f)
+        drfl_cb = DatetimeRotatingFileLogger(dir, raw"\c\o\m\p-YYYY-mm-dd-HH-MM.\l\o\g";
+                                             rotation_callback=callback)
 
-        sink = TeeLogger(drfl_sec, drfl_min, drfl_fmt)
+        sink = TeeLogger(drfl_min, drfl_hour, drfl_fmt, drfl_cb)
         with_logger(sink) do
-            while millisecond(now()) < 100 || millisecond(now()) > 200
-                sleep(0.001)
-            end
+            # Make sure to trigger one minute-level rotation and no hour-level
+            # rotation by sleeping until HH:MM:55
+            n = now()
+            sleeptime = mod((55 - second(n)), 60)
+            minute(n) == 59 && (sleeptime += 60)
+            sleep(sleeptime)
             @info "first"
             @info "second"
-            sleep(0.9)
+            sleep(10) # Should rotate to next minute
             @info("third")
         end
 
         # Drop anything that's not a .log file or empty
         files = sort(map(f -> joinpath(dir, f), readdir(dir)))
         files = filter(f -> endswith(f, ".log") && filesize(f) > 0, files)
-        sec_files = filter(f -> startswith(basename(f), "sec-"), files)
-        @test length(sec_files) == 2
-
         min_files = filter(f -> startswith(basename(f), "min-"), files)
-        @test length(min_files) == 1
+        @test length(min_files) == 2
+
+        hour_files = filter(f -> startswith(basename(f), "hour-"), files)
+        @test length(hour_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)
-        sec2_data = String(read(sec_files[2]))
-        @test occursin("third", sec2_data)
+        # Two files exist, but just one have been rotated
+        @test length(callback_record) == 1
+        @test occursin(r"comp-\d{4}(-\d{2}){4}\.log$", callback_record[1])
 
-        min_data = String(read(min_files[1]))
+        min1_data = String(read(min_files[1]))
+        @test occursin("first", min1_data)
+        @test occursin("second", min1_data)
+        min2_data = String(read(min_files[2]))
+        @test occursin("third", min2_data)
+
+        min_data = String(read(hour_files[1]))
         @test occursin("first", min_data)
         @test occursin("second", min_data)
         @test occursin("third", min_data)
@@ -168,6 +179,10 @@ end
         @test occursin("dnoces", fmt_data)
         fmt_data = String(read(fmt_files[2]))
         @test occursin("driht", fmt_data)
+
+        # Sub-minute resolution not allowed
+        @test_throws(ArgumentError("rotating the logger with sub-minute resolution not supported"),
+                     DatetimeRotatingFileLogger(dir, "HH-MM-SS"))
     end
 end