Merge pull request #32 from staticfloat/sf/rotating_logger

Add `DatetimeRotatingFileLogger`

Author: oxinabox

Project.toml

@@ -3,6 +3,9 @@ uuid = "e6f89c97-d47a-5376-807f-9c37f3926c36"
 authors = ["Lyndon White <[email protected]>"]
 version = "0.4.1"
 
+[deps]
+Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
+
 [compat]
 julia = "0.7, 1"
 

README.md

@@ -81,7 +81,7 @@ logger = global_logger()
 
 
 # Loggers introduced by this package:
-This package introduces 6 new loggers.
+This package introduces 7 new loggers.
 The `TeeLogger`, the `TransformerLogger`, 3 types of filtered logger, and the `FileLogger`.
 All of them just wrap existing loggers.
  - The `TeeLogger` sends the logs to multiple different loggers.
@@ -91,6 +91,7 @@ All of them just wrap existing loggers.
      - The `EarlyFilteredLogger` lets you write filter rules based on the `level`, `module`, `group` and `id` of the log message
      - The `ActiveFilteredLogger` lets you filter based on the full content
  - The `FileLogger` is a simple logger sink that writes to file.
+ - The `DatetimeRotatingFileLogger` is a logger sink that writes to file, rotating logs based upon a user-provided `DateFormat`.
 
 By combining `TeeLogger` with filter loggers you can arbitrarily route log messages, wherever you want.
 
@@ -290,6 +291,30 @@ It can also be used to do things such as change the log level of messages from a
 Or to set common properties for all log messages within the `with_logger` block,
 for example to set them all to the same `group`.
 
+## `DatetimeRotatingFileLogger`
+Use this sink to rotate your logs based upon a given `DateFormat`, automatically closing one file and opening another
+when the `DateFormat` would change the filename.  Note that if you wish to have static portions of your filename, you must
+escape them so they are not interpreted by the `DateFormat` code.  Example:
+
+```julia
+julia> using Logging, LoggingExtras
+
+julia> rotating_logger = DatetimeRotatingFileLogger(pwd(), raw"\a\c\c\e\s\s-YYYY-mm-dd-HH-MM-SS.\l\o\g");
+
+julia> with_logger(rotating_logger) do
+       @info("This goes in one file")
+       sleep(1.1)
+       @info("This goes in another file")
+       end
+
+julia> filter(f -> endswith(f, ".log"), readdir(pwd()))
+2-element Array{String,1}:
+ "access-2020-07-13-13-24-13.log"
+ "access-2020-07-13-13-24-14.log"
+```
+
+The user implicitly controls when the files will be rolled over based on the `DateFormat` given.
+
 # More Examples
 
 ## Filter out any overly long messages

src/LoggingExtras.jl

@@ -9,7 +9,8 @@ import Base.CoreLogging:
     handle_message, shouldlog, min_enabled_level, catch_exceptions
 
 export TeeLogger, TransformerLogger, FileLogger,
-    ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger
+    ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger,
+    DatetimeRotatingFileLogger
 
 
 ######
@@ -37,6 +38,7 @@ include("activefiltered.jl")
 include("earlyfiltered.jl")
 include("minlevelfiltered.jl")
 include("filelogger.jl")
+include("datetime_rotation.jl")
 include("deprecated.jl")
 
 end # module

src/datetime_rotation.jl

@@ -0,0 +1,98 @@
+using Dates
+import Base: isless
+
+raw"""
+    DatetimeRotatingFileLogger
+
+Constructs a FileLogger that rotates its file based on the current date.
+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:
+
+Usage example:
+
+    logger = DatetimeRotatingFileLogger(log_dir, raw"\a\c\c\e\s\s-YYYY-mm-dd.\l\o\g")
+"""
+mutable struct DatetimeRotatingFileLogger <: AbstractLogger
+    logger::SimpleLogger
+    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,
+    )
+end
+
+function reopen!(drfl::DatetimeRotatingFileLogger)
+    drfl.logger = SimpleLogger(open(calc_logpath(drfl.dir, drfl.filename_pattern), "a"), BelowMinLevel)
+    drfl.next_reopen_check = next_datetime_transition(drfl.filename_pattern)
+    return nothing
+end
+
+"""
+    next_datetime_transition(fmt::DateFormat)
+
+Given a DateFormat that is being applied to our filename, what is the next
+time at which our filepath will need to change?
+"""
+function next_datetime_transition(fmt::DateFormat)
+    extract_token(x::Dates.DatePart{T}) where {T} = T
+    token_timescales = Dict(
+        # Milliseconds is the smallest timescale
+        's' => Millisecond(1),
+        # Seconds
+        'S' => Second(1),
+        # Minutes
+        'M' => Minute(1),
+        # Hours
+        'I' => Hour(1),
+        'H' => Hour(1),
+        # Days
+        'd' => Day(1),
+        'e' => Day(1),
+        'E' => Day(1),
+        # Month
+        'm' => Month(1),
+        'u' => Month(1),
+        'U' => Month(1),
+        # Year
+        'y' => Year(1),
+        'Y' => Year(1),
+    )
+
+    # Dates for some reason explicitly does not define equality between the smaller
+    # timescales (Second, Minute, Day, etc..) and the larger, non-constant timescales
+    # (Month, Year).  We do so explicitly here, without committing type piracy:
+    custom_isless(x, y) = isless(x, y)
+    custom_isless(x::Union{Millisecond,Second,Minute,Hour,Day}, y::Union{Month, Year}) = true
+    custom_isless(x::Union{Month, Year}, y::Union{Millisecond,Second,Minute,Hour,Day}) = false
+
+    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)
+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)
+    end
+    handle_message(drfl.logger, args...; kwargs...)
+    drfl.always_flush && flush(drfl.logger.stream)
+end
+
+shouldlog(drfl::DatetimeRotatingFileLogger, arg...) = true
+min_enabled_level(drfl::DatetimeRotatingFileLogger) = BelowMinLevel
+catch_exceptions(drfl::DatetimeRotatingFileLogger) = catch_exceptions(drfl.logger)

test/runtests.jl

@@ -1,6 +1,7 @@
 using LoggingExtras
 using Test
 using Test: collect_test_logs, TestLogger
+using Dates
 
 using Base.CoreLogging
 using Base.CoreLogging: BelowMinLevel, Debug, Info, Warn, Error
@@ -121,19 +122,62 @@ end
     @test length(testlogger.logs) == 2
 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")
+        sink = TeeLogger(drfl_sec, drfl_min)
+        with_logger(sink) do
+            while millisecond(now()) < 100 || millisecond(now()) > 200
+                sleep(0.001)
+            end
+            @info "first"
+            @info "second"
+            sleep(0.9)
+            @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
+
+        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)
+
+        min_data = String(read(min_files[1]))
+        @test occursin("first", min_data)
+        @test occursin("second", min_data)
+        @test occursin("third", min_data)
+    end
+end
+
 
 @testset "Deprecations" begin
     testlogger = TestLogger(min_level=BelowMinLevel)
 
-    demux_logger = DemuxLogger(testlogger)
-    @test demux_logger isa TeeLogger
-    @test Set(demux_logger.loggers) == Set([testlogger, global_logger()])
+    @test_logs (:warn, r"deprecated") match_mode=:any begin
+        demux_logger = DemuxLogger(testlogger)
+        @test demux_logger isa TeeLogger
+        @test Set(demux_logger.loggers) == Set([testlogger, global_logger()])
+    end
 
-    demux_logger = DemuxLogger(testlogger; include_current_global=true)
-    @test demux_logger isa TeeLogger
-    @test Set(demux_logger.loggers) == Set([testlogger, global_logger()])
+    @test_logs (:warn, r"deprecated") match_mode=:any begin
+        demux_logger = DemuxLogger(testlogger; include_current_global=true)
+        @test demux_logger isa TeeLogger
+        @test Set(demux_logger.loggers) == Set([testlogger, global_logger()])
+    end
 
-    demux_logger = DemuxLogger(testlogger; include_current_global=false)
-    @test demux_logger isa TeeLogger
-    @test Set(demux_logger.loggers) == Set([testlogger])
+    @test_logs (:warn, r"deprecated") match_mode=:any begin
+        demux_logger = DemuxLogger(testlogger; include_current_global=false)
+        @test demux_logger isa TeeLogger
+        @test Set(demux_logger.loggers) == Set([testlogger])
+    end
 end