BazerUtils.jl

Assorted Julia utilities including custom logging
Log | Files | Refs | README | LICENSE

commit 9c59fca2318074f9951bdc373c628efb7aa9ede9
parent 78966386e5e79f208244f09d0cefb4d3474747c5
Author: Erik Loualiche <[email protected]>
Date:   Tue, 24 Mar 2026 17:13:06 -0500

Merge pull request #13 from LouLouLibs/feature/logger-cleanup

Logger cleanup: format expansion, thread safety, exact-level filtering
Diffstat:
M.gitignore | 3+++
MProject.toml | 2+-
Adocs/superpowers/plans/2026-03-24-logger-cleanup.md | 1270+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Adocs/superpowers/specs/2026-03-24-logger-cleanup-design.md | 182+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Msrc/BazerUtils.jl | 4++--
Msrc/CustomLogger.jl | 857++++++++++++++++++++++++++++++++++++++++++++-----------------------------------
Mtest/UnitTests/customlogger.jl | 370+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----
Mtest/runtests.jl | 1+
8 files changed, 2293 insertions(+), 396 deletions(-)

diff --git a/.gitignore b/.gitignore @@ -14,4 +14,7 @@ docs/node_modules/ *.jl.cov *.jl.mem /lcov.info + +# Worktrees +.worktrees/ # --------------------------------------------------------- diff --git a/Project.toml b/Project.toml @@ -1,7 +1,7 @@ name = "BazerUtils" uuid = "36dcebb2-80bb-4116-91f4-ed9f396c4a1c" authors = ["Erik Loualiche"] -version = "0.10.1" +version = "0.11.0" [deps] CodecZlib = "944b1d66-785c-5afd-91f1-9de20f533193" diff --git a/docs/superpowers/plans/2026-03-24-logger-cleanup.md b/docs/superpowers/plans/2026-03-24-logger-cleanup.md @@ -0,0 +1,1270 @@ +# Logger Cleanup & Format Expansion Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Rewrite CustomLogger.jl to fix robustness issues, add JSON/logfmt/log4j_standard formats, rename :log4j to :oneline, add exact-level filtering, and refactor to multiple dispatch. + +**Architecture:** Replace if/elseif format dispatch with Julia multiple dispatch on `LogFormat` subtypes. Each format implements `format_log(io, fmt, log_record, timestamp; kwargs...)`. FileSink gains per-stream `ReentrantLock`s with IO deduplication for single-file mode. `cascading_loglevels` kwarg controls `MinLevelLogger` vs exact `EarlyFilteredLogger`. + +**Tech Stack:** Julia 1.10+, LoggingExtras.jl (EarlyFilteredLogger, FormatLogger, MinLevelLogger, TeeLogger), Dates + +**Spec:** `docs/superpowers/specs/2026-03-24-logger-cleanup-design.md` + +--- + +### Task 1: Format types, resolve_format, and helper functions + +**Files:** +- Modify: `src/CustomLogger.jl` (replace lines 1-17 with new infrastructure, add helpers before format functions) +- Test: `test/UnitTests/customlogger.jl` + +- [ ] **Step 1: Write failing tests for resolve_format and helpers** + +Add at the **top** of the `@testset "CustomLogger"` block in `test/UnitTests/customlogger.jl`: + +```julia + @testset "resolve_format" begin + @test BazerUtils.resolve_format(:pretty) isa BazerUtils.PrettyFormat + @test BazerUtils.resolve_format(:oneline) isa BazerUtils.OnelineFormat + @test BazerUtils.resolve_format(:syslog) isa BazerUtils.SyslogFormat + @test BazerUtils.resolve_format(:json) isa BazerUtils.JsonFormat + @test BazerUtils.resolve_format(:logfmt) isa BazerUtils.LogfmtFormat + @test BazerUtils.resolve_format(:log4j_standard) isa BazerUtils.Log4jStandardFormat + @test_throws ArgumentError BazerUtils.resolve_format(:invalid_format) + # :log4j is deprecated alias for :oneline + @test BazerUtils.resolve_format(:log4j) isa BazerUtils.OnelineFormat + end + + @testset "get_module_name" begin + @test BazerUtils.get_module_name(nothing) == "unknown" + @test BazerUtils.get_module_name(Base) == "Base" + @test BazerUtils.get_module_name(Main) == "Main" + end + + @testset "json_escape" begin + @test BazerUtils.json_escape("hello") == "hello" + @test BazerUtils.json_escape("line1\nline2") == "line1\\nline2" + @test BazerUtils.json_escape("say \"hi\"") == "say \\\"hi\\\"" + @test BazerUtils.json_escape("back\\slash") == "back\\\\slash" + @test BazerUtils.json_escape("tab\there") == "tab\\there" + end + + @testset "logfmt_escape" begin + @test BazerUtils.logfmt_escape("simple") == "simple" + @test BazerUtils.logfmt_escape("has space") == "\"has space\"" + @test BazerUtils.logfmt_escape("has\"quote") == "\"has\\\"quote\"" + @test BazerUtils.logfmt_escape("has=equals") == "\"has=equals\"" + end +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: FAIL — `resolve_format`, `get_module_name`, `json_escape`, `logfmt_escape` not defined + +- [ ] **Step 3: Implement format types, resolve_format, and helpers** + +Replace lines 1–15 of `src/CustomLogger.jl` (everything ABOVE `abstract type LogSink end` on line 16 — keep `LogSink` and everything after it intact until Task 2) with: + +```julia +# ================================================================================================== +# CustomLogger.jl — Custom multi-sink logger with per-level filtering and pluggable formats +# ================================================================================================== + + +# --- Format types (multiple dispatch instead of if/elseif) --- + +abstract type LogFormat end +struct PrettyFormat <: LogFormat end +struct OnelineFormat <: LogFormat end +struct SyslogFormat <: LogFormat end +struct JsonFormat <: LogFormat end +struct LogfmtFormat <: LogFormat end +struct Log4jStandardFormat <: LogFormat end + +const VALID_FORMATS = "Valid options: :pretty, :oneline, :syslog, :json, :logfmt, :log4j_standard" + +""" + resolve_format(s::Symbol) -> LogFormat + +Map a format symbol to its LogFormat type. `:log4j` is a deprecated alias for `:oneline`. +""" +function resolve_format(s::Symbol)::LogFormat + s === :pretty && return PrettyFormat() + s === :oneline && return OnelineFormat() + s === :log4j && (Base.depwarn( + ":log4j is deprecated, use :oneline for single-line format or :log4j_standard for Apache Log4j format. :log4j will be removed in a future major version.", + :log4j); return OnelineFormat()) + s === :syslog && return SyslogFormat() + s === :json && return JsonFormat() + s === :logfmt && return LogfmtFormat() + s === :log4j_standard && return Log4jStandardFormat() + throw(ArgumentError("Unknown log_format: :$s. $VALID_FORMATS")) +end + + +# --- Helper functions --- + +""" + get_module_name(mod) -> String + +Extract module name as a string, returning "unknown" for `nothing`. +""" +get_module_name(mod::Module) = string(nameof(mod)) +get_module_name(::Nothing) = "unknown" + +""" + reformat_msg(log_record; displaysize=(50,100)) -> String + +Convert log record message to a string. Strings pass through; other types +are rendered via `show` with display size limits. +""" +function reformat_msg(log_record; displaysize::Tuple{Int,Int}=(50,100))::String + msg = log_record.message + msg isa AbstractString && return String(msg) + buf = IOBuffer() + show(IOContext(buf, :limit => true, :compact => true, :displaysize => displaysize), + "text/plain", msg) + return String(take!(buf)) +end + +""" + msg_to_singleline(message::AbstractString) -> String + +Collapse a multi-line message to a single line, using ` | ` as separator. +""" +function msg_to_singleline(message::AbstractString)::String + message |> + str -> replace(str, r"\"\"\"[\r\n\s]*(.+?)[\r\n\s]*\"\"\""s => s"\1") |> + str -> replace(str, r"\n\s*" => " | ") |> + str -> replace(str, r"\|\s*\|" => "|") |> + str -> replace(str, r"\s*\|\s*" => " | ") |> + str -> replace(str, r"\|\s*$" => "") |> + strip |> String +end + +""" + json_escape(s::AbstractString) -> String + +Escape a string for inclusion in a JSON value (without surrounding quotes). +""" +function json_escape(s::AbstractString)::String + s = replace(s, '\\' => "\\\\") + s = replace(s, '"' => "\\\"") + s = replace(s, '\n' => "\\n") + s = replace(s, '\r' => "\\r") + s = replace(s, '\t' => "\\t") + return s +end + +""" + logfmt_escape(s::AbstractString) -> String + +Format a value for logfmt output. Quotes the value if it contains spaces, equals, or quotes. +""" +function logfmt_escape(s::AbstractString)::String + needs_quoting = contains(s, ' ') || contains(s, '"') || contains(s, '=') + if needs_quoting + return "\"" * replace(s, '"' => "\\\"") * "\"" + end + return s +end +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: The new testsets pass. Existing tests may fail because old code was replaced — that's OK, we fix it in subsequent tasks. + +- [ ] **Step 5: Commit** + +```bash +git add src/CustomLogger.jl test/UnitTests/customlogger.jl +git commit -m "feat: add format types, resolve_format, and helper functions" +``` + +--- + +### Task 2: Refactor FileSink (finalizer, locks, IO deduplication) + +**Files:** +- Modify: `src/CustomLogger.jl` (the `FileSink` struct and related functions) +- Test: `test/UnitTests/customlogger.jl` + +- [ ] **Step 1: Write failing tests for FileSink** + +Add after the `logfmt_escape` testset: + +```julia + @testset "FileSink" begin + tmp = tempname() + # Single file mode: deduplicates IO handles + sink = BazerUtils.FileSink(tmp; create_files=false) + @test length(sink.ios) == 4 + @test length(unique(objectid.(sink.ios))) == 1 # all same IO + @test length(sink.locks) == 4 + @test length(unique(objectid.(sink.locks))) == 1 # all same lock + @test all(io -> io !== stdout && io !== stderr, sink.ios) + close(sink) + rm(tmp, force=true) + + # Multi file mode: separate IO handles + sink2 = BazerUtils.FileSink(tmp; create_files=true) + @test length(sink2.ios) == 4 + @test length(unique(objectid.(sink2.ios))) == 4 # all different IO + @test length(unique(objectid.(sink2.locks))) == 4 # all different locks + close(sink2) + rm.(BazerUtils.get_log_filenames(tmp; create_files=true), force=true) + + # close guard: closing twice doesn't error + sink3 = BazerUtils.FileSink(tempname(); create_files=false) + close(sink3) + @test_nowarn close(sink3) # second close is safe + end +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: FAIL — `sink.locks` doesn't exist, IO dedup not implemented + +- [ ] **Step 3: Implement refactored FileSink** + +Replace the `get_log_filenames` functions and `FileSink` struct (from after the helpers to the `Base.close` function) with: + +```julia +# --- LogSink infrastructure --- + +abstract type LogSink end + +""" + get_log_filenames(filename; file_loggers, create_files) -> Vector{String} + +Generate log file paths. When `create_files=true`, creates `filename_level.log` per level. +When `false`, repeats `filename` for all levels. +""" +function get_log_filenames(filename::AbstractString; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], + create_files::Bool=false) + if create_files + return [string(filename, "_", string(f), ".log") for f in file_loggers] + else + return repeat([filename], length(file_loggers)) + end +end + +function get_log_filenames(files::Vector{<:AbstractString}; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug]) + n = length(file_loggers) + length(files) != n && throw(ArgumentError( + "Expected exactly $n file paths (one per logger: $(join(file_loggers, ", "))), got $(length(files))")) + return files +end + +""" + FileSink <: LogSink + +File-based log sink with per-stream locking for thread safety. + +When all files point to the same path (single-file mode), IO handles and locks are +deduplicated — one IO and one lock shared across all slots. +""" +struct FileSink <: LogSink + files::Vector{String} + ios::Vector{IO} + locks::Vector{ReentrantLock} + + function FileSink(filename::AbstractString; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], + create_files::Bool=false) + files = get_log_filenames(filename; file_loggers=file_loggers, create_files=create_files) + if create_files + @info "Creating $(length(files)) log files:\n$(join(string.(" \u2B91 ", files), "\n"))" + else + @info "Single log sink: all levels writing to $filename" + end + # Deduplicate: open each unique path once, share IO + lock + unique_paths = unique(files) + path_to_io = Dict(p => open(p, "a") for p in unique_paths) + path_to_lock = Dict(p => ReentrantLock() for p in unique_paths) + ios = [path_to_io[f] for f in files] + locks = [path_to_lock[f] for f in files] + obj = new(files, ios, locks) + finalizer(close, obj) + return obj + end + + function FileSink(files::Vector{<:AbstractString}; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug]) + actual_files = get_log_filenames(files; file_loggers=file_loggers) + unique_paths = unique(actual_files) + path_to_io = Dict(p => open(p, "a") for p in unique_paths) + path_to_lock = Dict(p => ReentrantLock() for p in unique_paths) + ios = [path_to_io[f] for f in actual_files] + locks = [path_to_lock[f] for f in actual_files] + obj = new(actual_files, ios, locks) + finalizer(close, obj) + return obj + end +end + +function Base.close(sink::FileSink) + for io in unique(sink.ios) + io !== stdout && io !== stderr && isopen(io) && close(io) + end +end +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: FileSink tests pass. + +- [ ] **Step 5: Commit** + +```bash +git add src/CustomLogger.jl test/UnitTests/customlogger.jl +git commit -m "feat: refactor FileSink with locks, IO dedup, finalizer, close guard" +``` + +--- + +### Task 3: Implement format_log methods for all 6 formats + +**Files:** +- Modify: `src/CustomLogger.jl` (ADD new `format_log` methods AFTER the old format functions — keep old functions in place until Task 7 cleanup) +- Modify: `src/BazerUtils.jl` (add `Logging.Error` import needed for `get_color`) +- Test: `test/UnitTests/customlogger.jl` + +- [ ] **Step 1: Write failing tests for format_log** + +Add after the `FileSink` testset: + +```julia + @testset "format_log methods" begin + T = Dates.DateTime(2024, 1, 15, 14, 30, 0) + log_record = (level=Base.CoreLogging.Info, message="test message", + _module=BazerUtils, file="/src/app.jl", line=42, group=:test, id=:test) + nothing_record = (level=Base.CoreLogging.Info, message="nothing mod", + _module=nothing, file="test.jl", line=1, group=:test, id=:test) + + @testset "PrettyFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), log_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "test message") + @test contains(output, "14:30:00") + @test contains(output, "BazerUtils") + @test contains(output, "┌") + @test contains(output, "└") + end + + @testset "PrettyFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), nothing_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "unknown") + end + + @testset "OnelineFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), log_record, T; + displaysize=(50,100), shorten_path=:no) + output = String(take!(buf)) + @test contains(output, "INFO") + @test contains(output, "2024-01-15 14:30:00") + @test contains(output, "BazerUtils") + @test contains(output, "test message") + end + + @testset "OnelineFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), nothing_record, T; + displaysize=(50,100), shorten_path=:no) + output = String(take!(buf)) + @test contains(output, "unknown") + end + + @testset "SyslogFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), log_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "<14>") # facility=1, severity=6 -> (1*8)+6=14 + @test contains(output, "2024-01-15T14:30:00") + @test contains(output, "test message") + end + + @testset "JsonFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.JsonFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test startswith(output, "{") + @test endswith(output, "}") + @test contains(output, "\"timestamp\":\"2024-01-15T14:30:00\"") + @test contains(output, "\"level\":\"Info\"") + @test contains(output, "\"module\":\"BazerUtils\"") + @test contains(output, "\"message\":\"test message\"") + @test contains(output, "\"line\":42") + # Verify it parses as valid JSON + parsed = JSON.parse(output) + @test parsed["level"] == "Info" + @test parsed["line"] == 42 + end + + @testset "JsonFormat escaping" begin + escape_record = (level=Base.CoreLogging.Warn, message="line1\nline2 \"quoted\"", + _module=nothing, file="test.jl", line=1, group=:test, id=:test) + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.JsonFormat(), escape_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + parsed = JSON.parse(output) + @test parsed["message"] == "line1\nline2 \"quoted\"" + @test parsed["module"] == "unknown" + end + + @testset "LogfmtFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "ts=2024-01-15T14:30:00") + @test contains(output, "level=Info") + @test contains(output, "module=BazerUtils") + @test contains(output, "msg=\"test message\"") + end + + @testset "LogfmtFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), nothing_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "module=unknown") + end + + @testset "SyslogFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), nothing_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "nothing mod") + @test !contains(output, "nothing[") # should not show "nothing" as module in brackets + end + + @testset "Log4jStandardFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + # Pattern: timestamp LEVEL [threadid] module - message + @test contains(output, "2024-01-15 14:30:00,000") + @test contains(output, "INFO ") + @test contains(output, "BazerUtils") + @test contains(output, " - ") + @test contains(output, "test message") + end + + @testset "Log4jStandardFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), nothing_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "unknown") + @test contains(output, "nothing mod") + end + end +``` + +**IMPORTANT:** Also add `import Dates` to `test/runtests.jl` imports (after `import HTTP`). + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: FAIL — `format_log` not defined + +- [ ] **Step 3: Implement all format_log methods** + +Add to `src/CustomLogger.jl` AFTER the `shorten_path_str` function (at the end of the file). Keep old format functions (`format_pretty`, `format_log4j`, `format_syslog`, `get_color`, etc.) in place for now — they will be removed in Task 7: + +```julia +# --- Constants --- + +const SYSLOG_SEVERITY = Dict( + Logging.Info => 6, # Informational + Logging.Warn => 4, # Warning + Logging.Error => 3, # Error + Logging.Debug => 7 # Debug +) + +const JULIA_BIN = Base.julia_cmd().exec[1] + +# --- ANSI color helpers (for PrettyFormat) --- + +function get_color(level) + BOLD = "\033[1m" + LIGHT_BLUE = "\033[94m" + RED = "\033[31m" + GREEN = "\033[32m" + YELLOW = "\033[33m" + return level == Logging.Debug ? LIGHT_BLUE : + level == Logging.Info ? GREEN : + level == Logging.Warn ? "$YELLOW$BOLD" : + level == Logging.Error ? "$RED$BOLD" : + "\033[0m" +end + + +# ================================================================================================== +# format_log methods — one per LogFormat type +# All write directly to `io`. All accept a pre-computed `timestamp::DateTime`. +# ================================================================================================== + +function format_log(io, ::PrettyFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", + kwargs...) + + BOLD = "\033[1m" + EMPH = "\033[2m" + RESET = "\033[0m" + + date = format(timestamp, log_date_format) + time_str = format(timestamp, log_time_format) + ts = "$BOLD$(time_str)$RESET $EMPH$date$RESET" + + level_str = string(log_record.level) + color = get_color(log_record.level) + mod_name = get_module_name(log_record._module) + source = " @ $mod_name[$(log_record.file):$(log_record.line)]" + first_line = "┌ [$ts] $color$level_str$RESET | $source" + + formatted = reformat_msg(log_record; displaysize=displaysize) + lines = split(formatted, "\n") + + println(io, first_line) + for (i, line) in enumerate(lines) + prefix = i < length(lines) ? "│ " : "└ " + println(io, prefix, line) + end +end + +function format_log(io, ::OnelineFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + shorten_path::Symbol=:relative_path, + kwargs...) + + ts = format(timestamp, "yyyy-mm-dd HH:MM:SS") + level = rpad(uppercase(string(log_record.level)), 5) + mod_name = get_module_name(log_record._module) + file = shorten_path_str(log_record.file; strategy=shorten_path) + prefix = shorten_path === :relative_path ? "[$(pwd())] " : "" + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "$prefix$ts $level $mod_name[$file:$(log_record.line)] $msg") +end + +function format_log(io, ::SyslogFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, ISODateTimeFormat) + severity = get(SYSLOG_SEVERITY, log_record.level, 6) + pri = (1 * 8) + severity # facility=1 (user-level) + hostname = gethostname() + pid = getpid() + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "<$pri>1 $ts $hostname $JULIA_BIN $pid - - $msg") +end + +function format_log(io, ::JsonFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, ISODateTimeFormat) + level = json_escape(string(log_record.level)) + mod_name = json_escape(get_module_name(log_record._module)) + file = json_escape(string(log_record.file)) + line = log_record.line + msg = json_escape(reformat_msg(log_record; displaysize=displaysize)) + + println(io, "{\"timestamp\":\"$ts\",\"level\":\"$level\",\"module\":\"$mod_name\",\"file\":\"$file\",\"line\":$line,\"message\":\"$msg\"}") +end + +function format_log(io, ::LogfmtFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, ISODateTimeFormat) + level = string(log_record.level) + mod_name = get_module_name(log_record._module) + file = logfmt_escape(string(log_record.file)) + msg = logfmt_escape(reformat_msg(log_record; displaysize=displaysize)) + + println(io, "ts=$ts level=$level module=$mod_name file=$file line=$(log_record.line) msg=$msg") +end + +function format_log(io, ::Log4jStandardFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + # Apache Log4j PatternLayout: %d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%t] %c - %m%n + ts = format(timestamp, "yyyy-mm-dd HH:MM:SS") + millis = lpad(Dates.millisecond(timestamp), 3, '0') + level = rpad(uppercase(string(log_record.level)), 5) + thread_id = Threads.threadid() + mod_name = get_module_name(log_record._module) + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "$ts,$millis $level [$thread_id] $mod_name - $msg") +end +``` + +- [ ] **Step 4: Update BazerUtils.jl imports** + +Add `Logging.Error` to the Logging import line in `src/BazerUtils.jl`: + +```julia +import Logging: global_logger, Logging, Logging.Debug, Logging.Info, Logging.Warn, Logging.Error +``` + +- [ ] **Step 5: Run tests to verify format_log tests pass** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: All `format_log methods` tests pass. + +- [ ] **Step 6: Commit** + +```bash +git add src/CustomLogger.jl src/BazerUtils.jl test/UnitTests/customlogger.jl test/runtests.jl +git commit -m "feat: implement format_log methods for all 6 formats" +``` + +--- + +### Task 4: Rewrite custom_format, create_demux_logger, and custom_logger + +This task replaces the core orchestration. `custom_format` uses dispatch instead of if/elseif. `create_demux_logger` gains `cascading_loglevels` and thread-safe locking. `custom_logger` gets updated kwargs. + +**Files:** +- Modify: `src/CustomLogger.jl` (replace `custom_format`, `create_demux_logger`, `custom_logger`) + +**IMPORTANT: Steps 1-4 below are ATOMIC.** Apply all four before running tests. The intermediate states between steps will not compile because they reference each other's new signatures. + +- [ ] **Step 1: Rewrite custom_format** + +Replace the old `custom_format` function (the one with the if/elseif chain) with: + +```julia +# ================================================================================================== +# custom_format — dispatch hub. Called by FormatLogger callbacks. +# ================================================================================================== + +""" + custom_format(io, fmt::LogFormat, log_record::NamedTuple; kwargs...) + +Format and write a log record to `io` using the given format. Generates a single +timestamp and delegates to the appropriate `format_log` method. +""" +function custom_format(io, fmt::LogFormat, log_record::NamedTuple; + displaysize::Tuple{Int,Int}=(50,100), + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", + shorten_path::Symbol=:relative_path) + + timestamp = now() + format_log(io, fmt, log_record, timestamp; + displaysize=displaysize, + log_date_format=log_date_format, + log_time_format=log_time_format, + shorten_path=shorten_path) +end +``` + +- [ ] **Step 2: Rewrite create_demux_logger** + +Replace the old `create_demux_logger` with: + +```julia +# ================================================================================================== +# create_demux_logger — builds the TeeLogger pipeline +# ================================================================================================== + +function create_demux_logger(sink::FileSink, + file_loggers::Vector{Symbol}, + module_absolute_message_filter, + module_specific_message_filter, + fmt_file::LogFormat, + fmt_stdout::LogFormat, + format_kwargs::NamedTuple; + cascading_loglevels::Bool=false) + + logger_configs = Dict( + :error => (module_absolute_message_filter, Logging.Error), + :warn => (module_absolute_message_filter, Logging.Warn), + :info => (module_specific_message_filter, Logging.Info), + :debug => (module_absolute_message_filter, Logging.Debug) + ) + + logger_list = [] + + for (io_index, logger_key) in enumerate(file_loggers) + if !haskey(logger_configs, logger_key) + @warn "Unknown logger type: $logger_key — skipping" + continue + end + if io_index > length(sink.ios) + error("Not enough IO streams in sink for logger: $logger_key") + end + + message_filter, log_level = logger_configs[logger_key] + io = sink.ios[io_index] + lk = sink.locks[io_index] + + # Thread-safe format callback + format_cb = (cb_io, log_record) -> lock(lk) do + custom_format(cb_io, fmt_file, log_record; format_kwargs...) + end + + inner = EarlyFilteredLogger(message_filter, FormatLogger(format_cb, io)) + + if cascading_loglevels + # Old behavior: MinLevelLogger catches this level and above + push!(logger_list, MinLevelLogger(inner, log_level)) + else + # New behavior: exact level only + exact_filter = log -> log.level == log_level + push!(logger_list, EarlyFilteredLogger(exact_filter, inner)) + end + end + + # Stdout logger — always Info+, uses specific module filter, no file locking + stdout_format_cb = (io, log_record) -> custom_format(io, fmt_stdout, log_record; + format_kwargs...) + stdout_logger = MinLevelLogger( + EarlyFilteredLogger(module_specific_message_filter, + FormatLogger(stdout_format_cb, stdout)), + Logging.Info) + push!(logger_list, stdout_logger) + + return TeeLogger(logger_list...) +end +``` + +- [ ] **Step 3: Rewrite custom_logger (main method)** + +Replace the old `custom_logger(sink::LogSink; ...)` with: + +```julia +# ================================================================================================== +# custom_logger — public API +# ================================================================================================== + +""" + custom_logger(filename; kw...) + +Set up a custom global logger with per-level file output, module filtering, and configurable formatting. + +When `create_log_files=true`, creates one log file per level (e.g. `filename_error.log`). +Otherwise all levels write to the same file. + +# Arguments +- `filename::AbstractString`: base name for the log files +- `filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter from stdout and info-level file logs +- `filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter from all logs +- `file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug]`: which levels to capture +- `log_date_format::AbstractString="yyyy-mm-dd"`: date format in timestamps +- `log_time_format::AbstractString="HH:MM:SS"`: time format in timestamps +- `displaysize::Tuple{Int,Int}=(50,100)`: display size for non-string messages +- `log_format::Symbol=:oneline`: file log format (`:pretty`, `:oneline`, `:syslog`, `:json`, `:logfmt`, `:log4j_standard`) +- `log_format_stdout::Symbol=:pretty`: stdout format (same options) +- `shorten_path::Symbol=:relative_path`: path shortening strategy (`:oneline` format only) +- `cascading_loglevels::Bool=false`: when `true`, each file captures its level and above; when `false`, each file captures only its exact level +- `create_log_files::Bool=false`: create separate files per level +- `overwrite::Bool=false`: overwrite existing log files +- `create_dir::Bool=false`: create log directory if missing +- `verbose::Bool=false`: warn about filtering non-imported modules + +# Example +```julia +custom_logger("/tmp/myapp"; + filtered_modules_all=[:HTTP, :TranscodingStreams], + create_log_files=true, + overwrite=true, + log_format=:oneline) +``` +""" +function custom_logger( + sink::LogSink; + filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing, + filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing, + file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", + displaysize::Tuple{Int,Int}=(50,100), + log_format::Symbol=:oneline, + log_format_stdout::Symbol=:pretty, + shorten_path::Symbol=:relative_path, + cascading_loglevels::Bool=false, + verbose::Bool=false) + + # Resolve format types (validates symbols, handles :log4j deprecation) + fmt_file = resolve_format(log_format) + fmt_stdout = resolve_format(log_format_stdout) + + # Normalize file_loggers to Vector + file_loggers_vec = file_loggers isa Symbol ? [file_loggers] : collect(file_loggers) + + # Warn about filtering non-imported modules + if verbose + imported_modules = filter( + x -> typeof(getfield(Main, x)) <: Module && x !== :Main, + names(Main, imported=true)) + all_filters = Symbol[x for x in unique(vcat( + something(filtered_modules_specific, Symbol[]), + something(filtered_modules_all, Symbol[]))) if !isnothing(x)] + if !isempty(all_filters) + missing = filter(x -> x ∉ imported_modules, all_filters) + if !isempty(missing) + @warn "Filtering non-imported modules: $(join(string.(missing), ", "))" + end + end + end + + # Module filters + module_absolute_filter = create_module_filter(filtered_modules_all) + module_specific_filter = create_module_filter(filtered_modules_specific) + + format_kwargs = (displaysize=displaysize, + log_date_format=log_date_format, + log_time_format=log_time_format, + shorten_path=shorten_path) + + demux = create_demux_logger(sink, file_loggers_vec, + module_absolute_filter, module_specific_filter, + fmt_file, fmt_stdout, format_kwargs; + cascading_loglevels=cascading_loglevels) + + global_logger(demux) + return demux +end + +""" + create_module_filter(modules) -> Function + +Return a filter function that drops log messages from the specified modules. +Uses `startswith` to catch submodules (e.g. `:HTTP` catches `HTTP.ConnectionPool`). +""" +function create_module_filter(modules) + return function(log) + isnothing(modules) && return true + mod = string(log._module) + for m in modules + startswith(mod, string(m)) && return false + end + return true + end +end +``` + +- [ ] **Step 4: Rewrite convenience constructors** + +Replace the old convenience constructors: + +```julia +# Convenience constructor: filename or vector of filenames +function custom_logger( + filename::Union{AbstractString, Vector{<:AbstractString}}; + create_log_files::Bool=false, + overwrite::Bool=false, + create_dir::Bool=false, + file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], + kwargs...) + + file_loggers_array = file_loggers isa Symbol ? [file_loggers] : collect(file_loggers) + + files = if filename isa AbstractString + get_log_filenames(filename; file_loggers=file_loggers_array, create_files=create_log_files) + else + get_log_filenames(filename; file_loggers=file_loggers_array) + end + + # Create directories if needed + log_dirs = unique(dirname.(files)) + missing_dirs = filter(d -> !isempty(d) && !isdir(d), log_dirs) + if !isempty(missing_dirs) + if create_dir + @warn "Creating log directories: $(join(missing_dirs, ", "))" + mkpath.(missing_dirs) + else + @error "Log directories do not exist: $(join(missing_dirs, ", "))" + end + end + + overwrite && foreach(f -> rm(f, force=true), unique(files)) + + sink = if filename isa AbstractString + FileSink(filename; file_loggers=file_loggers_array, create_files=create_log_files) + else + FileSink(filename; file_loggers=file_loggers_array) + end + + custom_logger(sink; file_loggers=file_loggers, kwargs...) +end + +# Convenience for batch/script mode +function custom_logger(; kwargs...) + if !isempty(PROGRAM_FILE) + logbase = splitext(abspath(PROGRAM_FILE))[1] + custom_logger(logbase; kwargs...) + else + @error "custom_logger() with no arguments requires a script context (PROGRAM_FILE is empty in the REPL)" + end +end +``` + +- [ ] **Step 5: Run full test suite** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: The new unit tests pass. Some existing integration tests may fail due to the `:log4j` → `:oneline` default change and `cascading_loglevels=false` default. That's expected — we fix those in Task 6. + +- [ ] **Step 6: Commit** + +```bash +git add src/CustomLogger.jl +git commit -m "feat: rewrite custom_format, create_demux_logger, custom_logger with dispatch and cascading_loglevels" +``` + +--- + +### Task 5: Write tests for new features (cascading_loglevels, new formats, thread safety) + +**Files:** +- Modify: `test/UnitTests/customlogger.jl` + +- [ ] **Step 1: Add cascading_loglevels tests** + +Add after existing integration tests: + +```julia + # -- exact level filtering (default: cascading_loglevels=false) + log_path_cl = joinpath(tempdir(), "log_cascading") + logger_exact = custom_logger( + log_path_cl; + overwrite=true, create_log_files=true) + @error "ONLY_ERROR" + @warn "ONLY_WARN" + @info "ONLY_INFO" + @debug "ONLY_DEBUG" + log_files_exact = get_log_names(logger_exact) + content_exact = read.(log_files_exact, String) + # Positive: each file has its own level + @test contains(content_exact[1], "ONLY_ERROR") + @test contains(content_exact[2], "ONLY_WARN") + @test contains(content_exact[3], "ONLY_INFO") + @test contains(content_exact[4], "ONLY_DEBUG") + # Negative: each file does NOT have other levels + @test !contains(content_exact[1], "ONLY_WARN") + @test !contains(content_exact[1], "ONLY_INFO") + @test !contains(content_exact[1], "ONLY_DEBUG") + @test !contains(content_exact[2], "ONLY_ERROR") + @test !contains(content_exact[2], "ONLY_INFO") + @test !contains(content_exact[2], "ONLY_DEBUG") + @test !contains(content_exact[3], "ONLY_ERROR") + @test !contains(content_exact[3], "ONLY_WARN") + @test !contains(content_exact[3], "ONLY_DEBUG") + @test !contains(content_exact[4], "ONLY_ERROR") + @test !contains(content_exact[4], "ONLY_WARN") + @test !contains(content_exact[4], "ONLY_INFO") + close_logger(logger_exact, remove_files=true) + + # -- cascading level filtering (cascading_loglevels=true, old behavior) + logger_cascade = custom_logger( + log_path_cl; + overwrite=true, create_log_files=true, + cascading_loglevels=true) + @error "CASCADE_ERROR" + @warn "CASCADE_WARN" + @info "CASCADE_INFO" + @debug "CASCADE_DEBUG" + log_files_cascade = get_log_names(logger_cascade) + content_cascade = read.(log_files_cascade, String) + # Error file: only errors + @test contains(content_cascade[1], "CASCADE_ERROR") + @test !contains(content_cascade[1], "CASCADE_WARN") + # Warn file: warn + error + @test contains(content_cascade[2], "CASCADE_WARN") + @test contains(content_cascade[2], "CASCADE_ERROR") + # Info file: info + warn + error + @test contains(content_cascade[3], "CASCADE_INFO") + @test contains(content_cascade[3], "CASCADE_WARN") + @test contains(content_cascade[3], "CASCADE_ERROR") + # Debug file: everything + @test contains(content_cascade[4], "CASCADE_DEBUG") + @test contains(content_cascade[4], "CASCADE_INFO") + @test contains(content_cascade[4], "CASCADE_WARN") + @test contains(content_cascade[4], "CASCADE_ERROR") + close_logger(logger_cascade, remove_files=true) +``` + +- [ ] **Step 2: Add integration tests for new formats** + +```julia + # -- JSON format logger + log_path_fmt = joinpath(tempdir(), "log_fmt") + logger_json = custom_logger( + log_path_fmt; + log_format=:json, overwrite=true) + @error "JSON_ERROR" + @info "JSON_INFO" + log_file_json = get_log_names(logger_json)[1] + json_lines = filter(!isempty, split(read(log_file_json, String), "\n")) + for line in json_lines + parsed = JSON.parse(line) + @test haskey(parsed, "timestamp") + @test haskey(parsed, "level") + @test haskey(parsed, "module") + @test haskey(parsed, "message") + end + close_logger(logger_json, remove_files=true) + + # -- logfmt format logger + logger_logfmt = custom_logger( + log_path_fmt; + log_format=:logfmt, overwrite=true) + @error "LOGFMT_ERROR" + @info "LOGFMT_INFO" + log_file_logfmt = get_log_names(logger_logfmt)[1] + logfmt_content = read(log_file_logfmt, String) + @test contains(logfmt_content, "level=Error") + @test contains(logfmt_content, "level=Info") + @test contains(logfmt_content, r"ts=\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}") + @test contains(logfmt_content, "msg=") + close_logger(logger_logfmt, remove_files=true) + + # -- log4j_standard format logger + logger_l4js = custom_logger( + log_path_fmt; + log_format=:log4j_standard, overwrite=true) + @error "L4JS_ERROR" + @info "L4JS_INFO" + log_file_l4js = get_log_names(logger_l4js)[1] + l4js_content = read(log_file_l4js, String) + # Pattern: timestamp,millis LEVEL [threadid] module - message + @test contains(l4js_content, r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} ERROR") + @test contains(l4js_content, r"INFO .* - L4JS_INFO") + @test contains(l4js_content, " - ") + close_logger(logger_l4js, remove_files=true) +``` + +- [ ] **Step 3: Add unknown format and deprecation tests** + +```julia + # -- unknown format throws + @test_throws ArgumentError custom_logger( + joinpath(tempdir(), "log_bad"); log_format=:banana, overwrite=true) + + # -- :log4j deprecated alias still works + logger_deprecated = custom_logger( + log_path_fmt; + log_format=:log4j, overwrite=true) + @info "DEPRECATED_TEST" + log_file_dep = get_log_names(logger_deprecated)[1] + dep_content = read(log_file_dep, String) + @test contains(dep_content, "DEPRECATED_TEST") + close_logger(logger_deprecated, remove_files=true) +``` + +- [ ] **Step 4: Add thread safety test** + +```julia + # -- thread safety: concurrent logging produces complete lines + log_path_thread = joinpath(tempdir(), "log_thread") + logger_thread = custom_logger( + log_path_thread; + log_format=:json, overwrite=true) + n_tasks = 10 + n_msgs = 50 + @sync for t in 1:n_tasks + Threads.@spawn begin + for m in 1:n_msgs + @info "task=$t msg=$m" + end + end + end + log_file_thread = get_log_names(logger_thread)[1] + flush(logger_thread.loggers[end].logger.logger.stream) # flush stdout logger is irrelevant + # Flush all file streams + for lg in logger_thread.loggers + s = lg.logger.logger.stream + s isa IOStream && flush(s) + end + thread_lines = filter(!isempty, split(read(log_file_thread, String), "\n")) + # Every line should be valid JSON (no interleaving) + for line in thread_lines + @test startswith(line, "{") + @test endswith(line, "}") + parsed = JSON.parse(line) + @test haskey(parsed, "message") + end + close_logger(logger_thread, remove_files=true) +``` + +- [ ] **Step 5: Run tests (with threads for thread safety test)** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --threads=4 --project -e 'using Pkg; Pkg.test()'` +Expected: New tests pass. Some old integration tests may still need updating (Task 6). **Note:** `--threads=4` is required so the thread safety test actually exercises concurrent writes. + +- [ ] **Step 6: Commit** + +```bash +git add test/UnitTests/customlogger.jl +git commit -m "test: add tests for cascading_loglevels, new formats, thread safety" +``` + +--- + +### Task 6: Update existing tests for breaking changes + +The `cascading_loglevels=false` default changes behavior of the `[:debug, :info]` partial-loggers test. The `:log4j` format references in existing tests should use `:oneline` (or keep `:log4j` for the deprecation test, already covered). + +**Files:** +- Modify: `test/UnitTests/customlogger.jl` + +- [ ] **Step 1: Fix the partial file_loggers test** + +The test at the end that uses `file_loggers = [:debug, :info]` expects cascading behavior where the debug file contains INFO messages. With `cascading_loglevels=false`, each file is exact-level. Update the test: + +Old assertion: +```julia +@test contains.(log_content, r"INFO .* INFO MESSAGE") == [true, true] +``` + +Change to: +```julia +@test contains.(log_content, r"DEBUG .* DEBUG MESSAGE") == [true, false] +@test contains.(log_content, r"INFO .* INFO MESSAGE") == [false, true] +``` + +- [ ] **Step 2: Update existing format tests to use :oneline** + +In the "logger with formatting" test block, change `log_format=:log4j` to `log_format=:oneline`. +In the "logger with formatting and truncation" test block, change `log_format=:log4j` to `log_format=:oneline`. + +- [ ] **Step 3: Update _module=nothing test to use :oneline** + +Change `log_format=:log4j` to `log_format=:oneline` in the `_module=nothing` test. Also update the `custom_format` call to use the new dispatch signature: + +```julia + # -- logger with _module=nothing (issue #10) + logger_single = custom_logger( + log_path; + log_format=:oneline, + overwrite=true) + log_record = (level=Base.CoreLogging.Info, message="test nothing module", + _module=nothing, file="test.jl", line=1, group=:test, id=:test) + buf = IOBuffer() + BazerUtils.custom_format(buf, BazerUtils.OnelineFormat(), log_record; + shorten_path=:no) + output = String(take!(buf)) + @test contains(output, "unknown") + @test contains(output, "test nothing module") + close_logger(logger_single, remove_files=true) +``` + +- [ ] **Step 4: Run full test suite** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: ALL tests pass. + +- [ ] **Step 5: Commit** + +```bash +git add test/UnitTests/customlogger.jl +git commit -m "test: update existing tests for :oneline rename and cascading_loglevels=false default" +``` + +--- + +### Task 7: Clean up dead code and update docstrings + +**Files:** +- Modify: `src/CustomLogger.jl` — remove any leftover old code +- Modify: `src/BazerUtils.jl` — verify imports are clean + +- [ ] **Step 1: Remove old format functions and dead code** + +DELETE from `src/CustomLogger.jl`: +- Old `format_pretty` function (was kept alongside new `format_log` methods since Task 3) +- Old `format_log4j` function +- Old `format_syslog` function +- Old `custom_format` with if/elseif chain (replaced in Task 4) +- Old `create_demux_logger` signature (replaced in Task 4) +- Old `reformat_msg` with `log_format` kwarg (replaced in Task 1) +- Old `syslog_severity_map` dict with string keys (replaced by `SYSLOG_SEVERITY`) +- Old `julia_bin` const (replaced by `JULIA_BIN`) +- Old `get_color` function (replaced by new `get_color` in Task 3 — verify no duplication) +- Commented-out blocks in old `format_syslog` +- Orphaned section-separator comment blocks (`# ----...`) + +- [ ] **Step 2: Verify BazerUtils.jl imports** + +Ensure `src/BazerUtils.jl` imports include `Logging.Error` and that no unused imports remain: + +```julia +import Dates: format, now, Dates, ISODateTimeFormat +import Logging: global_logger, Logging, Logging.Debug, Logging.Info, Logging.Warn, Logging.Error +import LoggingExtras: EarlyFilteredLogger, FormatLogger, MinLevelLogger, TeeLogger +import JSON: JSON +import Tables: Tables +import CodecZlib: CodecZlib +``` + +- [ ] **Step 3: Run full test suite** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: ALL tests pass. + +- [ ] **Step 4: Commit** + +```bash +git add src/CustomLogger.jl src/BazerUtils.jl +git commit -m "chore: remove dead code and clean up imports" +``` + +--- + +### Task 8: Version bump to v0.11.0 + +**Files:** +- Modify: `Project.toml` + +- [ ] **Step 1: Bump version** + +Change `version = "0.10.1"` to `version = "0.11.0"` in `Project.toml`. + +- [ ] **Step 2: Add TODO comment for log4j deprecation timeline** + +Add a comment in `src/CustomLogger.jl` near the `resolve_format` function: + +```julia +# TODO (March 2027): Remove :log4j alias for :oneline. Rename :log4j_standard to :log4j. +# This is a breaking change requiring a major version bump. +``` + +- [ ] **Step 3: Run full test suite one final time** + +Run: `cd /Users/loulou/Dropbox/projects_code/julia_packages/BazerUtils.jl && julia --project -e 'using Pkg; Pkg.test()'` +Expected: ALL tests pass. + +- [ ] **Step 4: Commit** + +```bash +git add Project.toml src/CustomLogger.jl +git commit -m "chore: bump version to v0.11.0 (breaking: cascading_loglevels default, :log4j renamed)" +``` diff --git a/docs/superpowers/specs/2026-03-24-logger-cleanup-design.md b/docs/superpowers/specs/2026-03-24-logger-cleanup-design.md @@ -0,0 +1,182 @@ +# BazerUtils.jl Logger Cleanup & Format Expansion + +**Date:** 2026-03-24 +**Scope:** CustomLogger.jl rewrite — robustness, new formats, breaking changes +**Version target:** v0.11.0 (breaking) + +## Summary + +Rewrite the logging subsystem to fix robustness issues, add three new output formats (JSON, logfmt, log4j_standard), rename the misleading `:log4j` symbol to `:oneline`, introduce exact-level file filtering, and refactor the format dispatch from if/elseif chains to multiple dispatch on format types. + +## Format Lineup + +Six active formats plus one deprecated alias: + +| Symbol | Description | Use case | +|--------|-------------|----------| +| `:pretty` | Box-drawing + ANSI colors | Stdout, human reading | +| `:oneline` | Single-line with timestamp, level, module, file:line, message | File logs, simple grep | +| `:syslog` | RFC 5424 syslog | Syslog collectors | +| `:json` | One JSON object per line (hand-rolled, no JSON.jl dependency) | Structured log aggregation (ELK, Datadog, Loki) | +| `:logfmt` | `key=value` pairs | Splunk, Heroku, grep-friendly structured | +| `:log4j_standard` | Actual Apache Log4j PatternLayout (`%d %-5p [%t] %c - %m%n`) | Java tooling interop | +| `:log4j` | **Deprecated alias** for `:oneline` — emits one-time `Base.depwarn` | Backwards compat only | + +### JSON format (zero-dependency) + +Hand-rolled serializer. Log records are flat with known types (strings, ints, symbols), so we only need string escaping + concatenation. No JSON.jl required. + +Output: +```json +{"timestamp":"2024-01-15T14:30:00","level":"ERROR","module":"MyApp","file":"src/app.jl","line":42,"message":"Something failed"} +``` + +### logfmt format + +``` +ts=2024-01-15T14:30:00 level=error module=MyApp file=src/app.jl line=42 msg="Something failed" +``` + +### log4j_standard format + +Follows Apache Log4j PatternLayout convention: +``` +2024-01-15 14:30:00,123 ERROR [1] MyApp - Something failed +``` + +Where `[1]` is the Julia thread ID (analogous to Java's `[%t]` thread name). + +### Deprecation timeline + +- **v0.11.0 (now):** `:log4j` = deprecated alias for `:oneline`, `:log4j_standard` = real Apache format +- **~March 2027:** Remove `:log4j` alias, rename `:log4j_standard` to `:log4j`, bump major version + +## Bug Fixes & Robustness + +### 1. FileSink finalizer + +Register `finalizer(close, obj)` in the `FileSink` constructor so GC cleans up leaked file handles. The `close` method must guard against closing `stdout`/`stderr` (defensive check: `if io !== stdout && io !== stderr`). + +### 2. Thread safety + +Add `locks::Vector{ReentrantLock}` to `FileSink`. When `create_files=false` (all streams write to the same file), use a **single shared lock** for all streams. When `create_files=true` (separate files), use one lock per stream. Wrap all `println(io, ...)` calls in `lock(lk) do ... end`. `ReentrantLock` (not `SpinLock`) to handle re-entrant logging from `show` methods. + +Implementation: deduplicate IO handles when all files point to the same path — open the file once and share the IO + lock across all slots. This eliminates the aliased-file race condition. + +### 3. `_module=nothing` in all formats + +All six format methods must defensively handle `log_record._module === nothing`, falling back to `"unknown"`. Currently only `format_log4j` has this fix (v0.10.1). The three new formats (json, logfmt, log4j_standard) must include it from the start, and `format_pretty` needs the same fix applied. + +### 4. Unknown log_format throws + +`custom_format` will `throw(ArgumentError("Unknown log_format: :$log_format. Valid options: :pretty, :oneline, :syslog, :json, :logfmt, :log4j_standard"))` instead of silently producing no output. + +### 5. reformat_msg double-call + +Remove the dead `reformat_msg` call at top of `custom_format` (line 292). Each format function already calls it independently. + +### 6. get_log_filenames(::Vector) inconsistency + +Require exactly `length(file_loggers)` files. Throw `ArgumentError` for any other count. Remove the warn-for->4-then-truncate path. + +### 7. Single timestamp per log entry + +Call `now()` once in `custom_format` and pass the resulting `DateTime` to each format function. All three existing format functions (`format_pretty` line 370, `format_log4j` line 397, `format_syslog` line 425) currently call `now()` independently — these internal calls must all be removed and replaced with the passed-in timestamp parameter. Eliminates timestamp drift between capture and format. + +## Breaking Changes + +### cascading_loglevels + +New kwarg `cascading_loglevels::Bool=false`: + +- **`false` (new default):** Each file logger captures only its exact level. The error file gets errors only, the warn file gets warns only, etc. Implemented by replacing `MinLevelLogger` with an `EarlyFilteredLogger` that checks `log.level == target_level`. Non-standard log levels (arbitrary integers) are silently dropped under exact filtering — this is acceptable since custom levels are rare and users who need them can use `cascading_loglevels=true`. +- **`true` (old behavior):** Uses `MinLevelLogger` so each file captures its level and above (debug file gets everything, info gets info+warn+error, etc.). + +### log_format default symbol + +Default value changes from `:log4j` to `:oneline`. Functionally identical — same format, different name. + +## Architecture: Multiple Dispatch Refactor + +Replace the if/elseif chain in `custom_format` with dispatch on format types: + +```julia +abstract type LogFormat end +struct PrettyFormat <: LogFormat end +struct OnelineFormat <: LogFormat end +struct SyslogFormat <: LogFormat end +struct JsonFormat <: LogFormat end +struct LogfmtFormat <: LogFormat end +struct Log4jStandardFormat <: LogFormat end +``` + +A `resolve_format` function maps symbols to types (handling the `:log4j` deprecation here): + +```julia +function resolve_format(s::Symbol)::LogFormat + s == :pretty && return PrettyFormat() + s == :oneline && return OnelineFormat() + s == :log4j && (Base.depwarn("...", :log4j); return OnelineFormat()) + s == :syslog && return SyslogFormat() + s == :json && return JsonFormat() + s == :logfmt && return LogfmtFormat() + s == :log4j_standard && return Log4jStandardFormat() + throw(ArgumentError("Unknown log_format: :$s")) +end +``` + +Each format implements a method that **writes directly to `io`** (not returns a string): +```julia +format_log(io, fmt::PrettyFormat, log_record, timestamp; kwargs...) +``` + +All format methods write directly to `io` so that the thread-safe lock wraps the entire format+write. The pretty format's multi-line box-drawing output (header + continuation lines + last line) is written as multiple `println` calls within the same locked block. + +**`reformat_msg` refactor:** The current `reformat_msg` has a format-aware branch (`:color=>true` for pretty). Under the new dispatch, `reformat_msg` becomes format-unaware — it always returns a plain string. Pretty format adds color via ANSI codes in its own `format_log` method, not via `IOContext(:color=>true)` in `reformat_msg`. + +**`shorten_path` applicability:** Only `:oneline` uses `shorten_path` (as the current `:log4j` does). The new formats (`:json`, `:logfmt`, `:log4j_standard`) use the raw file path. All formats are available for both `log_format` (file) and `log_format_stdout`. + +**Deprecation warning text:** `":log4j is deprecated, use :oneline for single-line format or :log4j_standard for Apache Log4j format. :log4j will be removed in a future major version."` + +**File organization:** All format types, `resolve_format`, and `format_log` methods stay in `CustomLogger.jl`. The file is small enough that splitting is unnecessary. + +Shared logic (timestamp formatting, message reformatting, single-lining) lives in helper functions called by the format methods, not in a shared preamble. + +## Thread Safety Architecture + +The locking must happen at the `FormatLogger` callback level, since that's where `println(io, ...)` occurs. The `FileSink` owns the locks, and the format callback closures capture both the IO stream and its corresponding lock: + +```julia +format_log_file = (io, log_record) -> lock(sink.locks[i]) do + custom_format(io, fmt, log_record, now(); kwargs...) +end +``` + +This ensures the entire format+write is atomic per stream. + +## Testing Plan + +### New format tests +- `:json` — verify output parses as valid JSON, all expected keys present, string escaping works (newlines, quotes, backslashes in messages) +- `:logfmt` — verify key=value structure, quoted values with spaces, no unescaped quotes +- `:log4j_standard` — verify matches `%d %-5p [%t] %c - %m%n` pattern +- `:oneline` — existing tests adapted to use new symbol name + +### Behavior tests +- `cascading_loglevels=false` — each file has only its level's messages; **negative assertions** that error file does NOT contain warn/info/debug, warn file does NOT contain error/info/debug, etc. +- `cascading_loglevels=true` — old cascading behavior preserved; error file has errors only, warn file has warn+error, info has info+warn+error, debug has everything +- Unknown format symbol — throws `ArgumentError` +- `:log4j` symbol — works but emits deprecation warning +- `_module=nothing` — works in all six formats + +### Thread safety test +- Spawn N tasks each logging M messages concurrently +- Read the log file, verify no interleaved partial lines (every line is a complete log entry) + +### Robustness tests +- FileSink finalizer — verify files are closeable after GC (hard to test deterministically, but verify `close(sink)` works) + +## Out of Scope (Future PRs) + +- **Log rotation** — file size limits, file renaming, count limits +- **`:log4j` alias removal** — ~March 2027, rename `:log4j_standard` to `:log4j` diff --git a/src/BazerUtils.jl b/src/BazerUtils.jl @@ -2,8 +2,8 @@ module BazerUtils # -------------------------------------------------------------------------------------------------- -import Dates: format, now, Dates, ISODateTimeFormat -import Logging: global_logger, Logging, Logging.Debug, Logging.Info, Logging.Warn +import Dates: format, now, Dates +import Logging: global_logger, Logging, Logging.Debug, Logging.Info, Logging.Warn, Logging.Error import LoggingExtras: EarlyFilteredLogger, FormatLogger, MinLevelLogger, TeeLogger import JSON: JSON import Tables: Tables diff --git a/src/CustomLogger.jl b/src/CustomLogger.jl @@ -1,473 +1,466 @@ -# -------------------------------------------------------------------------------------------------- +# ================================================================================================== +# CustomLogger.jl — Custom multi-sink logger with per-level filtering and pluggable formats +# ================================================================================================== -# CustomLogger.jl -# Function to create a custom logger -# -------------------------------------------------------------------------------------------------- +# --- Format types (multiple dispatch instead of if/elseif) --- +abstract type LogFormat end +struct PrettyFormat <: LogFormat end +struct OnelineFormat <: LogFormat end +struct SyslogFormat <: LogFormat end +struct JsonFormat <: LogFormat end +struct LogfmtFormat <: LogFormat end +struct Log4jStandardFormat <: LogFormat end -# -------------------------------------------------------------------------------------------------- -# Exported function -# custom_logger -# -------------------------------------------------------------------------------------------------- +const VALID_FORMATS = "Valid options: :pretty, :oneline, :syslog, :json, :logfmt, :log4j_standard" +""" + resolve_format(s::Symbol) -> LogFormat + +Map a format symbol to its LogFormat type. `:log4j` is a deprecated alias for `:oneline`. +""" +# TODO (March 2027): Remove :log4j alias for :oneline. Rename :log4j_standard to :log4j. +# This is a breaking change requiring a major version bump. +function resolve_format(s::Symbol)::LogFormat + s === :pretty && return PrettyFormat() + s === :oneline && return OnelineFormat() + s === :log4j && (Base.depwarn( + ":log4j is deprecated, use :oneline for single-line format or :log4j_standard for Apache Log4j format. :log4j will be removed in a future major version.", + :log4j); return OnelineFormat()) + s === :syslog && return SyslogFormat() + s === :json && return JsonFormat() + s === :logfmt && return LogfmtFormat() + s === :log4j_standard && return Log4jStandardFormat() + throw(ArgumentError("Unknown log_format: :$s. $VALID_FORMATS")) +end + + +# --- Helper functions --- + +""" + get_module_name(mod) -> String + +Extract module name as a string, returning "unknown" for `nothing`. +""" +get_module_name(mod::Module) = string(nameof(mod)) +get_module_name(::Nothing) = "unknown" + +""" + reformat_msg(log_record; displaysize=(50,100)) -> String + +Convert log record message to a string. Strings pass through; other types +are rendered via `show` with display size limits. +""" +function reformat_msg(log_record; displaysize::Tuple{Int,Int}=(50,100))::String + msg = log_record.message + msg isa AbstractString && return String(msg) + buf = IOBuffer() + show(IOContext(buf, :limit => true, :compact => true, :displaysize => displaysize), + "text/plain", msg) + return String(take!(buf)) +end + +""" + msg_to_singleline(message::AbstractString) -> String + +Collapse a multi-line message to a single line, using ` | ` as separator. +""" +function msg_to_singleline(message::AbstractString)::String + message |> + str -> replace(str, r"\"\"\"[\r\n\s]*(.+?)[\r\n\s]*\"\"\""s => s"\1") |> + str -> replace(str, r"\n\s*" => " | ") |> + str -> replace(str, r"\|\s*\|" => "|") |> + str -> replace(str, r"\s*\|\s*" => " | ") |> + str -> replace(str, r"\|\s*$" => "") |> + strip |> String +end + +""" + json_escape(s::AbstractString) -> String + +Escape a string for inclusion in a JSON value (without surrounding quotes). +""" +function json_escape(s::AbstractString)::String + s = replace(s, '\\' => "\\\\") + s = replace(s, '"' => "\\\"") + s = replace(s, '\n' => "\\n") + s = replace(s, '\r' => "\\r") + s = replace(s, '\t' => "\\t") + return s +end + +""" + logfmt_escape(s::AbstractString) -> String + +Format a value for logfmt output. Quotes the value if it contains spaces, equals, or quotes. +""" +function logfmt_escape(s::AbstractString)::String + needs_quoting = contains(s, ' ') || contains(s, '"') || contains(s, '=') + if needs_quoting + return "\"" * replace(s, '"' => "\\\"") * "\"" + end + return s +end + + +# --- LogSink infrastructure --- -# -------------------------------------------------------------------------------------------------- abstract type LogSink end -# Helper function to get filenames -function get_log_filenames(filename::AbstractString; - file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], - create_files::Bool=false) +# Keep the active sink alive so the finalizer does not close it prematurely +# while the global logger is still writing to its IO handles. +const _active_sink = Ref{Union{Nothing, LogSink}}(nothing) +""" + get_log_filenames(filename; file_loggers, create_files) -> Vector{String} + +Generate log file paths. When `create_files=true`, creates `filename_level.log` per level. +When `false`, repeats `filename` for all levels. +""" +function get_log_filenames(filename::AbstractString; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], + create_files::Bool=false) if create_files - files = map(f -> "$(filename)_$(string(f)).log", file_loggers) - # files = ["$(filename)_error.log", "$(filename)_warn.log", - # "$(filename)_info.log", "$(filename)_debug.log"] + return [string(filename, "_", string(f), ".log") for f in file_loggers] else - files = repeat([filename], length(file_loggers)) + return repeat([filename], length(file_loggers)) end - return files end -function get_log_filenames(files::Vector{<:AbstractString}) - length(files) > 4 && (@warn "Please provide adequate number of logs (4 for sinks)") - length(files) < 4 && throw(ArgumentError("Must provide at least 4 file paths")) - return files[1:min(4, length(files))] +function get_log_filenames(files::Vector{<:AbstractString}; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug]) + n = length(file_loggers) + length(files) != n && throw(ArgumentError( + "Expected exactly $n file paths (one per logger: $(join(file_loggers, ", "))), got $(length(files))")) + return files end -struct FileSink <: LogSink +""" + FileSink <: LogSink + +File-based log sink with per-stream locking for thread safety. + +When all files point to the same path (single-file mode), IO handles and locks are +deduplicated — one IO and one lock shared across all slots. +""" +mutable struct FileSink <: LogSink files::Vector{String} ios::Vector{IO} + locks::Vector{ReentrantLock} - function FileSink(filename::AbstractString; - file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], + function FileSink(filename::AbstractString; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug], create_files::Bool=false) - files = get_log_filenames(filename; file_loggers=file_loggers, create_files=create_files) if create_files - @info "Creating $(length(files)) different files for logging ... \n \u2B91\t$(join(files, "\n\t"))" + @info "Creating $(length(files)) log files:\n$(join(string.(" \u2B91 ", files), "\n"))" else - @info "Only one sink provided ... \n\tAll logs will be written without differentiation on $filename" + @info "Single log sink: all levels writing to $filename" end - ios = [open(f, "a") for f in files] - new(files, ios) + # Deduplicate: open each unique path once, share IO + lock + unique_paths = unique(files) + path_to_io = Dict(p => open(p, "a") for p in unique_paths) + path_to_lock = Dict(p => ReentrantLock() for p in unique_paths) + ios = [path_to_io[f] for f in files] + locks = [path_to_lock[f] for f in files] + obj = new(files, ios, locks) + finalizer(close, obj) + return obj end - function FileSink(files::Vector{<:AbstractString}) - actual_files = get_log_filenames(files) - ios = [open(f, "a") for f in actual_files] - new(actual_files, ios) + function FileSink(files::Vector{<:AbstractString}; + file_loggers::Vector{Symbol}=[:error, :warn, :info, :debug]) + actual_files = get_log_filenames(files; file_loggers=file_loggers) + unique_paths = unique(actual_files) + path_to_io = Dict(p => open(p, "a") for p in unique_paths) + path_to_lock = Dict(p => ReentrantLock() for p in unique_paths) + ios = [path_to_io[f] for f in actual_files] + locks = [path_to_lock[f] for f in actual_files] + obj = new(actual_files, ios, locks) + finalizer(close, obj) + return obj end end -# Add finalizer to handle cleanup function Base.close(sink::FileSink) - foreach(close, sink.ios) + for io in unique(sink.ios) + io !== stdout && io !== stderr && isopen(io) && close(io) + end end # -------------------------------------------------------------------------------------------------- -# -------------------------------------------------------------------------------------------------- -""" - custom_logger(filename; kw...) - -Set up a custom global logger with per-level file output, module filtering, and configurable formatting. +# ================================================================================================== +# custom_format — dispatch hub. Called by FormatLogger callbacks. +# ================================================================================================== -When `create_log_files=true`, creates one log file per level (e.g. `filename_error.log`, `filename_warn.log`, etc.). -Otherwise all levels write to the same file. - -# Arguments -- `filename::AbstractString`: base name for the log files -- `filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter out of stdout and info-level file logs only (e.g. `[:TranscodingStreams]`) -- `filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter out of all logs (e.g. `[:HTTP]`) -- `file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug]`: which file loggers to register -- `log_date_format::AbstractString="yyyy-mm-dd"`: date format in log timestamps -- `log_time_format::AbstractString="HH:MM:SS"`: time format in log timestamps -- `displaysize::Tuple{Int,Int}=(50,100)`: display size for non-string log messages -- `log_format::Symbol=:log4j`: format for file logs (`:log4j`, `:pretty`, or `:syslog`) -- `log_format_stdout::Symbol=:pretty`: format for stdout -- `shorten_path::Symbol=:relative_path`: path shortening strategy for log4j format -- `create_log_files::Bool=false`: create separate files per log level -- `overwrite::Bool=false`: overwrite existing log files -- `create_dir::Bool=false`: create the log directory if it doesn't exist -- `verbose::Bool=false`: warn about filtering non-imported modules - -# Example -```julia -custom_logger("/tmp/myapp"; - filtered_modules_all=[:HTTP, :TranscodingStreams], - create_log_files=true, - overwrite=true, - log_format=:log4j) -``` """ -function custom_logger( - sink::LogSink; - filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing, - filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing, - file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], - log_date_format::AbstractString="yyyy-mm-dd", - log_time_format::AbstractString="HH:MM:SS", - displaysize::Tuple{Int,Int}=(50,100), - log_format::Symbol=:log4j, - log_format_stdout::Symbol=:pretty, - shorten_path::Symbol=:relative_path, - verbose::Bool=false) - - # warning if some non imported get filtered ... - imported_modules = filter((x) -> typeof(getfield(Main, x)) <: Module && x ≠ :Main, - names(Main, imported=true)) - all_filters = Symbol[x for x in unique(vcat( - something(filtered_modules_specific, Symbol[]), - something(filtered_modules_all, Symbol[]))) if !isnothing(x)] - if !isempty(all_filters) && verbose - catch_nonimported = map(x -> x ∈ imported_modules, all_filters) - if !all(catch_nonimported) - @warn "Some non (directly) imported modules are being filtered ... $(join(string.(all_filters[.!catch_nonimported]), ", "))" - end - end + custom_format(io, fmt::LogFormat, log_record::NamedTuple; kwargs...) - # Create a log filter that drops messages from the given modules. - # Uses startswith to also catch submodules (e.g. :HTTP catches HTTP.ConnectionPool). - function create_module_filter(modules) - return function(log) - if isnothing(modules) - return true - end - module_name = string(log._module) - for m in modules - if startswith(module_name, string(m)) - return false - end - end - return true - end - end - module_absolute_message_filter = create_module_filter(filtered_modules_all) - module_specific_message_filter = create_module_filter(filtered_modules_specific) - - - format_log_stdout = (io,log_record)->custom_format(io, log_record; - displaysize=displaysize, - log_date_format=log_date_format, - log_time_format=log_time_format, - log_format=log_format_stdout) +Format and write a log record to `io` using the given format. Generates a single +timestamp and delegates to the appropriate `format_log` method. +""" +function custom_format(io, fmt::LogFormat, log_record::NamedTuple; + displaysize::Tuple{Int,Int}=(50,100), + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", + shorten_path::Symbol=:relative_path) - format_log_file = (io,log_record)->custom_format(io, log_record; + timestamp = now() + format_log(io, fmt, log_record, timestamp; displaysize=displaysize, log_date_format=log_date_format, log_time_format=log_time_format, - log_format=log_format, shorten_path=shorten_path) - - demux_logger = create_demux_logger(sink, file_loggers, - module_absolute_message_filter, module_specific_message_filter, format_log_file, format_log_stdout) - - - - global_logger(demux_logger) - - - return demux_logger end -# -------------------------------------------------------------------------------------------------- -# -------------------------------------------------------------------------------------------------- -# Convenience constructor that creates appropriate sink -function custom_logger( - filename::Union{AbstractString, Vector{AbstractString}}; - create_log_files::Bool=false, - overwrite::Bool=false, - create_dir::Bool=false, - file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], - kwargs...) - - file_loggers_array = file_loggers isa Symbol ? [file_loggers] : file_loggers +# ================================================================================================== +# create_demux_logger — builds the TeeLogger pipeline +# ================================================================================================== - files = get_log_filenames(filename; - file_loggers=file_loggers_array, create_files=create_log_files) +function create_demux_logger(sink::FileSink, + file_loggers::Vector{Symbol}, + module_absolute_message_filter, + module_specific_message_filter, + fmt_file::LogFormat, + fmt_stdout::LogFormat, + format_kwargs::NamedTuple; + cascading_loglevels::Bool=false) - # create directory if needed and bool true - # returns an error if directory does not exist and bool false - log_dirs = unique(dirname.(files)) - missing_dirs = filter(d -> !isempty(d) && !isdir(d), log_dirs) - if create_dir && !isempty(missing_dirs) - @warn "Creating directory for logs ... $(join(missing_dirs, ", "))" - mkpath.(missing_dirs) - elseif !isempty(missing_dirs) - @error "Directory for logs does not exist ... $(join(missing_dirs, ", "))" - end - # Handle cleanup if needed - overwrite && foreach(f -> rm(f, force=true), files) - # Create sink - sink = FileSink(filename; - file_loggers=file_loggers_array, create_files=create_log_files) - # Call main logger function - custom_logger(sink; file_loggers=file_loggers, kwargs...) -end + logger_configs = Dict( + :error => (module_absolute_message_filter, Logging.Error), + :warn => (module_absolute_message_filter, Logging.Warn), + :info => (module_specific_message_filter, Logging.Info), + :debug => (module_absolute_message_filter, Logging.Debug) + ) + logger_list = [] -# Convenience for batch mode: uses PROGRAM_FILE as the log filename base -function custom_logger(; kwargs...) - if !isempty(PROGRAM_FILE) - logbase = splitext(abspath(PROGRAM_FILE))[1] - custom_logger(logbase; kwargs...) - else - @error "custom_logger() with no arguments requires a script context (PROGRAM_FILE is empty in the REPL)" - end -end -# -------------------------------------------------------------------------------------------------- + for (io_index, logger_key) in enumerate(file_loggers) + if !haskey(logger_configs, logger_key) + @warn "Unknown logger type: $logger_key — skipping" + continue + end + if io_index > length(sink.ios) + error("Not enough IO streams in sink for logger: $logger_key") + end + message_filter, log_level = logger_configs[logger_key] + io = sink.ios[io_index] + lk = sink.locks[io_index] -# -------------------------------------------------------------------------------------------------- -function create_demux_logger(sink, - file_loggers::Union{Symbol, Vector{Symbol}}, - module_absolute_message_filter, - module_specific_message_filter, - format_log_file, - format_log_stdout) - - # Convert single symbol to vector for consistency - loggers_to_include = file_loggers isa Symbol ? [file_loggers] : file_loggers - - logger_configs = Dict( - :error => (1, module_absolute_message_filter, Logging.Error), - :warn => (2, module_absolute_message_filter, Logging.Warn), - :info => (3, module_specific_message_filter, Logging.Info), - :debug => (4, module_absolute_message_filter, Logging.Debug) - ) + # Thread-safe format callback + format_cb = (cb_io, log_record) -> lock(lk) do + custom_format(cb_io, fmt_file, log_record; format_kwargs...) + end - logger_list = [] + inner = EarlyFilteredLogger(message_filter, FormatLogger(format_cb, io)) - io_index = 1 - for logger_key in loggers_to_include - if haskey(logger_configs, logger_key) - if io_index > length(sink.ios) - error("Not enough IO streams in sink for logger: $logger_key") - end - - _, message_filter, log_level = logger_configs[logger_key] - - file_logger = MinLevelLogger( - EarlyFilteredLogger(message_filter, - FormatLogger(format_log_file, sink.ios[io_index])), - log_level) - - push!(logger_list, file_logger) - io_index += 1 + if cascading_loglevels + # Old behavior: MinLevelLogger catches this level and above + push!(logger_list, MinLevelLogger(inner, log_level)) else - @warn "Unknown logger type: $logger_key" + # New behavior: exact level only + exact_filter = log -> log.level == log_level + push!(logger_list, EarlyFilteredLogger(exact_filter, inner)) end end - - # Always include stdout logger + + # Stdout logger — always Info+, uses specific module filter, no file locking + stdout_format_cb = (io, log_record) -> custom_format(io, fmt_stdout, log_record; + format_kwargs...) stdout_logger = MinLevelLogger( - EarlyFilteredLogger(module_specific_message_filter, - FormatLogger(format_log_stdout, stdout)), + EarlyFilteredLogger(module_specific_message_filter, + FormatLogger(stdout_format_cb, stdout)), Logging.Info) - push!(logger_list, stdout_logger) - - # Create and return the TeeLogger - return TeeLogger(logger_list...) + return TeeLogger(logger_list...) end -# -------------------------------------------------------------------------------------------------- -# -------------------------------------------------------------------------------------------------- -# Custom format function with box-drawing characters for wrap-around effect -# TODO should rewrite for multiple dispatch with different types for log_format -function custom_format(io, log_record::NamedTuple; - displaysize::Tuple{Int,Int}=(50,100), - log_date_format::AbstractString="yyyy-mm-dd", - log_time_format::AbstractString="HH:MM:SS", - log_format::Symbol=:pretty, # available pretty or log4j - shorten_path::Symbol=:relative_path # see function below tried to emulate p10k - ) - - # -- format the message!!! - formatted_message = reformat_msg(log_record; displaysize=displaysize) - - if log_format == :pretty - - prefix_continuation_line = "│ " - prefix_last_line = "└ " - - (first_line, message_lines) = format_pretty(log_record; - log_date_format=log_date_format, log_time_format=log_time_format) - - println(io, "$first_line") - for (index, line) in enumerate(message_lines) - if index < length(message_lines) - println(io, "$prefix_continuation_line$line") - else # Last line - println(io, "$prefix_last_line$line") - end - end +# ================================================================================================== +# custom_logger — public API +# ================================================================================================== - elseif log_format == :log4j - log_entry = log_record |> - str -> format_log4j(str, shorten_path=shorten_path) |> msg_to_singleline - println(io, log_entry) - elseif log_format == :syslog - log_entry = log_record |> format_syslog |> msg_to_singleline - println(io, log_entry) - end +""" + custom_logger(filename; kw...) +Set up a custom global logger with per-level file output, module filtering, and configurable formatting. -end - +When `create_log_files=true`, creates one log file per level (e.g. `filename_error.log`). +Otherwise all levels write to the same file. -# --- general functions -""" - reformat_msg - # we view strings as simple and everything else as complex +# Arguments +- `filename::AbstractString`: base name for the log files +- `filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter from stdout and info-level file logs +- `filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing`: modules to filter from all logs +- `file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug]`: which levels to capture +- `log_date_format::AbstractString="yyyy-mm-dd"`: date format in timestamps +- `log_time_format::AbstractString="HH:MM:SS"`: time format in timestamps +- `displaysize::Tuple{Int,Int}=(50,100)`: display size for non-string messages +- `log_format::Symbol=:oneline`: file log format (`:pretty`, `:oneline`, `:syslog`, `:json`, `:logfmt`, `:log4j_standard`) +- `log_format_stdout::Symbol=:pretty`: stdout format (same options) +- `shorten_path::Symbol=:relative_path`: path shortening strategy (`:oneline` format only) +- `cascading_loglevels::Bool=false`: when `true`, each file captures its level and above; when `false`, each file captures only its exact level +- `create_log_files::Bool=false`: create separate files per level +- `overwrite::Bool=false`: overwrite existing log files +- `create_dir::Bool=false`: create log directory if missing +- `verbose::Bool=false`: warn about filtering non-imported modules + +# Example +```julia +custom_logger("/tmp/myapp"; + filtered_modules_all=[:HTTP, :TranscodingStreams], + create_log_files=true, + overwrite=true, + log_format=:oneline) +``` """ -function reformat_msg(log_record; +function custom_logger( + sink::LogSink; + filtered_modules_specific::Union{Nothing, Vector{Symbol}}=nothing, + filtered_modules_all::Union{Nothing, Vector{Symbol}}=nothing, + file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", displaysize::Tuple{Int,Int}=(50,100), - log_format::Symbol=:pretty)::AbstractString - - if log_record.message isa AbstractString - return log_record.message - else - buf = IOBuffer() - if log_format == :pretty - show(IOContext(buf, :limit=>true, :compact=>true, :color=>true, :displaysize=>displaysize), - "text/plain", log_record.message) - else # log_format == :log4j - show(IOContext(buf, :limit => true, :compact => true, :displaysize => (50, 100)), - "text/plain", log_record.message) + log_format::Symbol=:oneline, + log_format_stdout::Symbol=:pretty, + shorten_path::Symbol=:relative_path, + cascading_loglevels::Bool=false, + verbose::Bool=false) + + # Resolve format types (validates symbols, handles :log4j deprecation) + fmt_file = resolve_format(log_format) + fmt_stdout = resolve_format(log_format_stdout) + + # Normalize file_loggers to Vector + file_loggers_vec = file_loggers isa Symbol ? [file_loggers] : collect(file_loggers) + + # Warn about filtering non-imported modules + if verbose + imported_modules = filter( + x -> isdefined(Main, x) && typeof(getfield(Main, x)) <: Module && x !== :Main, + names(Main, imported=true)) + all_filters = Symbol[x for x in unique(vcat( + something(filtered_modules_specific, Symbol[]), + something(filtered_modules_all, Symbol[]))) if !isnothing(x)] + if !isempty(all_filters) + missing_mods = filter(x -> x ∉ imported_modules, all_filters) + if !isempty(missing_mods) + @warn "Filtering non-imported modules: $(join(string.(missing_mods), ", "))" + end end - formatted_message = String(take!(buf)) end - return formatted_message -end - - -function msg_to_singleline(message::AbstractString)::AbstractString - message |> - str -> replace(str, r"\"\"\"[\r\n\s]*(.+?)[\r\n\s]*\"\"\""s => s"\1") |> - str -> replace(str, r"\n\s*" => " | ") |> - str -> replace(str, r"\|\s*\|" => "|") |> - str -> replace(str, r"\s*\|\s*" => " | ") |> - str -> replace(str, r"\|\s*$" => "") |> - strip -end + # Module filters + module_absolute_filter = create_module_filter(filtered_modules_all) + module_specific_filter = create_module_filter(filtered_modules_specific) -# --- pretty format -function format_pretty(log_record::NamedTuple; - log_date_format::AbstractString="yyyy-mm-dd", - log_time_format::AbstractString="HH:MM:SS", - )::Tuple{AbstractString, Vector{AbstractString}} + format_kwargs = (displaysize=displaysize, + log_date_format=log_date_format, + log_time_format=log_time_format, + shorten_path=shorten_path) - BOLD = "\033[1m" - EMPH = "\033[2m" - RESET = "\033[0m" - T = now() - - date = format(T, log_date_format) - time = format(T, log_time_format) - timestamp = "$BOLD$time$RESET $EMPH$date$RESET" # Apply bold only to the time - log_level = log_record.level - level = string(log_level) - color = get_color(log_level) - module_name = log_record._module - file = log_record.file - line = log_record.line - source_info = " @ $module_name[$file:$line]" - # Prepare the first part of the message prefix - first_line = "┌ [$timestamp] $color$level\033[0m | $source_info" + demux = create_demux_logger(sink, file_loggers_vec, + module_absolute_filter, module_specific_filter, + fmt_file, fmt_stdout, format_kwargs; + cascading_loglevels=cascading_loglevels) - formatted_message = reformat_msg(log_record, log_format=:pretty) + # Keep sink alive to prevent GC from closing IO handles + _active_sink[] = sink - message_lines = split(formatted_message, "\n") + global_logger(demux) + return demux +end - return (first_line, message_lines) +""" + create_module_filter(modules) -> Function +Return a filter function that drops log messages from the specified modules. +Uses `startswith` to catch submodules (e.g. `:HTTP` catches `HTTP.ConnectionPool`). +""" +function create_module_filter(modules) + return function(log) + isnothing(modules) && return true + mod = string(log._module) + for m in modules + startswith(mod, string(m)) && return false + end + return true + end end -# --- log4j format -function format_log4j(log_record::NamedTuple; - shorten_path::Symbol=:relative_path)::AbstractString - - timestamp = format(now(), "yyyy-mm-dd HH:MM:SS") - log_level = rpad(uppercase(string(log_record.level)), 5) - module_name = isnothing(log_record._module) ? :unknown : nameof(log_record._module) - file = shorten_path_str(log_record.file; strategy=shorten_path) - prefix = shorten_path == :relative_path ? "[$(pwd())] " : "" - line = log_record.line - formatted_message = reformat_msg(log_record, log_format=:log4j) +# Convenience constructor: filename or vector of filenames +function custom_logger( + filename::Union{AbstractString, Vector{<:AbstractString}}; + create_log_files::Bool=false, + overwrite::Bool=false, + create_dir::Bool=false, + file_loggers::Union{Symbol, Vector{Symbol}}=[:error, :warn, :info, :debug], + kwargs...) - log_entry = "$prefix$timestamp $log_level $module_name[$file:$line] $(replace(formatted_message, "\n" => " | "))" - - return log_entry + file_loggers_array = file_loggers isa Symbol ? [file_loggers] : collect(file_loggers) -end + files = if filename isa AbstractString + get_log_filenames(filename; file_loggers=file_loggers_array, create_files=create_log_files) + else + get_log_filenames(filename; file_loggers=file_loggers_array) + end -# --- syslog format! -# ----- for syslog mapping of severity! -const syslog_severity_map = Dict( # look at get color to get something nicer than a string call - "Info" => 6, # Informational - "Warn" => 4, # Warning - "Error" => 3, # Error - "Debug" => 7 # Debugging - ) -# ----- where are the binaries! -const julia_bin = Base.julia_cmd().exec[1] + # Create directories if needed + log_dirs = unique(dirname.(files)) + missing_dirs = filter(d -> !isempty(d) && !isdir(d), log_dirs) + if !isempty(missing_dirs) + if create_dir + @warn "Creating log directories: $(join(missing_dirs, ", "))" + mkpath.(missing_dirs) + else + @error "Log directories do not exist: $(join(missing_dirs, ", "))" + end + end + overwrite && foreach(f -> rm(f, force=true), unique(files)) -function format_syslog(log_record::NamedTuple)::AbstractString + sink = if filename isa AbstractString + FileSink(filename; file_loggers=file_loggers_array, create_files=create_log_files) + else + FileSink(filename; file_loggers=file_loggers_array) + end - timestamp = Dates.format(now(), ISODateTimeFormat) - file = log_record.file - severity = get(syslog_severity_map, string(log_record.level), 6) # Default to INFO - facility = 1 # User-level messages - pri = (facility * 8) + severity - hostname = gethostname() - pid = getpid() - # msg_id = haskey(log_record.metadata, "msg_id") ? log_record.metadata["msg_id"] : "-" # TODO - app_name = julia_bin - # msg_id = metadata["msg_id"] if haskey(metadata, "msg_id") else "-" - msg_id = "-" - # # Format structured data - # structured_data = "" - # if !isempty(metadata) - # structured_data = "[" * join(["exp@32473 $(k)=\"$(v)\"" for (k, v) in metadata if k != "msg_id"], " ") * "]" - # else - structured_data = "-" - # end - formatted_message = reformat_msg(log_record, log_format=:syslog) - - # we put everything on one line for clear logging ... - log_entry = "<$pri>1 $timestamp $hostname $app_name $pid $msg_id $structured_data $(replace(formatted_message, "\n" => " | "))" - # Print the log entry println(io, log_entry) - return log_entry + custom_logger(sink; file_loggers=file_loggers, kwargs...) +end +# Convenience for batch/script mode +function custom_logger(; kwargs...) + if !isempty(PROGRAM_FILE) + logbase = splitext(abspath(PROGRAM_FILE))[1] + custom_logger(logbase; kwargs...) + else + @error "custom_logger() with no arguments requires a script context (PROGRAM_FILE is empty in the REPL)" + end end -# --- pretty format -#-- colors for pretty -function get_color(level) +# --- Helper: colors for pretty format --- + +function get_color(level) RESET = "\033[0m" BOLD = "\033[1m" - # ITALIC = LIGHT_BLUE = "\033[94m" RED = "\033[31m" GREEN = "\033[32m" YELLOW = "\033[33m" - return level == Logging.Debug ? LIGHT_BLUE : # Use light blue for Debug + return level == Logging.Debug ? LIGHT_BLUE : level == Logging.Info ? GREEN : level == Logging.Warn ? "$YELLOW$BOLD" : level == Logging.Error ? "$RED$BOLD" : - RESET # Default to no specific color + RESET end -# -------------------------------------------------------------------------------------------------- # -------------------------------------------------------------------------------------------------- @@ -502,12 +495,12 @@ julia> shorten_path_str("/home/user/documents/very_long_filename.txt", strategy= "/home/user/doc…ents/very_…name.txt" ``` """ -function shorten_path_str(path::AbstractString; - max_length::Int=40, +function shorten_path_str(path::AbstractString; + max_length::Int=40, strategy::Symbol=:truncate_middle )::AbstractString - if strategy == :no + if strategy == :no return path elseif strategy == :relative_path return "./" * relpath(path, pwd()) @@ -521,7 +514,7 @@ function shorten_path_str(path::AbstractString; # Split path into components parts = split(path, '/') is_absolute = startswith(path, '/') - + # Handle empty path or root directory if isempty(parts) || (length(parts) == 1 && isempty(parts[1])) return is_absolute ? "/" : "" @@ -538,7 +531,7 @@ function shorten_path_str(path::AbstractString; result = join(shortened, "/") return is_absolute ? "/$result" : result end - + elseif strategy == :truncate_middle # For each component, truncate the middle if it's too long function shorten_component(comp::AbstractString; max_comp_len::Int=10) @@ -595,7 +588,7 @@ function shorten_path_str(path::AbstractString; push!(shortened, prefix) end end - + result = join(shortened, "/") return is_absolute ? "/$result" : result end @@ -606,5 +599,119 @@ end # -------------------------------------------------------------------------------------------------- +# --- Constants for format_log methods --- + +const SYSLOG_SEVERITY = Dict( + Logging.Info => 6, + Logging.Warn => 4, + Logging.Error => 3, + Logging.Debug => 7 +) + +const JULIA_BIN = Base.julia_cmd().exec[1] + + +# ================================================================================================== +# format_log methods — one per LogFormat type +# All write directly to `io`. All accept a pre-computed `timestamp::DateTime`. +# ================================================================================================== + +function format_log(io, ::PrettyFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + log_date_format::AbstractString="yyyy-mm-dd", + log_time_format::AbstractString="HH:MM:SS", + kwargs...) + + BOLD = "\033[1m" + EMPH = "\033[2m" + RESET = "\033[0m" + + date = format(timestamp, log_date_format) + time_str = format(timestamp, log_time_format) + ts = "$BOLD$(time_str)$RESET $EMPH$date$RESET" + + level_str = string(log_record.level) + color = get_color(log_record.level) + mod_name = get_module_name(log_record._module) + source = " @ $mod_name[$(log_record.file):$(log_record.line)]" + first_line = "┌ [$ts] $color$level_str$RESET | $source" + formatted = reformat_msg(log_record; displaysize=displaysize) + lines = split(formatted, "\n") + println(io, first_line) + for (i, line) in enumerate(lines) + prefix = i < length(lines) ? "│ " : "└ " + println(io, prefix, line) + end +end + +function format_log(io, ::OnelineFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + shorten_path::Symbol=:relative_path, + kwargs...) + + ts = format(timestamp, "yyyy-mm-dd HH:MM:SS") + level = rpad(uppercase(string(log_record.level)), 5) + mod_name = get_module_name(log_record._module) + file = shorten_path_str(log_record.file; strategy=shorten_path) + prefix = shorten_path === :relative_path ? "[$(pwd())] " : "" + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "$prefix$ts $level $mod_name[$file:$(log_record.line)] $msg") +end + +function format_log(io, ::SyslogFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, "yyyy-mm-ddTHH:MM:SS") + severity = get(SYSLOG_SEVERITY, log_record.level, 6) + pri = (1 * 8) + severity + hostname = gethostname() + pid = getpid() + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "<$pri>1 $ts $hostname $JULIA_BIN $pid - - $msg") +end + +function format_log(io, ::JsonFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, "yyyy-mm-ddTHH:MM:SS") + level = json_escape(uppercase(string(log_record.level))) + mod_name = json_escape(get_module_name(log_record._module)) + file = json_escape(string(log_record.file)) + line = log_record.line + msg = json_escape(reformat_msg(log_record; displaysize=displaysize)) + + println(io, "{\"timestamp\":\"$ts\",\"level\":\"$level\",\"module\":\"$mod_name\",\"file\":\"$file\",\"line\":$line,\"message\":\"$msg\"}") +end + +function format_log(io, ::LogfmtFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = Dates.format(timestamp, "yyyy-mm-ddTHH:MM:SS") + level = lowercase(string(log_record.level)) + mod_name = get_module_name(log_record._module) + file = logfmt_escape(string(log_record.file)) + msg = logfmt_escape(reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline) + + println(io, "ts=$ts level=$level module=$mod_name file=$file line=$(log_record.line) msg=$msg") +end + +function format_log(io, ::Log4jStandardFormat, log_record::NamedTuple, timestamp::Dates.DateTime; + displaysize::Tuple{Int,Int}=(50,100), + kwargs...) + + ts = format(timestamp, "yyyy-mm-dd HH:MM:SS") + millis = lpad(Dates.millisecond(timestamp), 3, '0') + level = rpad(uppercase(string(log_record.level)), 5) + thread_id = Threads.threadid() + mod_name = get_module_name(log_record._module) + msg = reformat_msg(log_record; displaysize=displaysize) |> msg_to_singleline + + println(io, "$ts,$millis $level [$thread_id] $mod_name - $msg") +end diff --git a/test/UnitTests/customlogger.jl b/test/UnitTests/customlogger.jl @@ -11,8 +11,8 @@ function close_logger(logger::TeeLogger; remove_files::Bool=false) # Get filenames before closing - filenames = get_log_names(logger) - + filenames = get_log_names(logger) + # Close all IOStreams for min_logger in logger.loggers stream = min_logger.logger.logger.stream @@ -28,10 +28,208 @@ log_path = joinpath.(tempdir(), "log") - # -- logger with everything in one place ... + @testset "resolve_format" begin + @test BazerUtils.resolve_format(:pretty) isa BazerUtils.PrettyFormat + @test BazerUtils.resolve_format(:oneline) isa BazerUtils.OnelineFormat + @test BazerUtils.resolve_format(:syslog) isa BazerUtils.SyslogFormat + @test BazerUtils.resolve_format(:json) isa BazerUtils.JsonFormat + @test BazerUtils.resolve_format(:logfmt) isa BazerUtils.LogfmtFormat + @test BazerUtils.resolve_format(:log4j_standard) isa BazerUtils.Log4jStandardFormat + @test_throws ArgumentError BazerUtils.resolve_format(:invalid_format) + # :log4j is deprecated alias for :oneline + @test BazerUtils.resolve_format(:log4j) isa BazerUtils.OnelineFormat + end + + @testset "get_module_name" begin + @test BazerUtils.get_module_name(nothing) == "unknown" + @test BazerUtils.get_module_name(Base) == "Base" + @test BazerUtils.get_module_name(Main) == "Main" + end + + @testset "json_escape" begin + @test BazerUtils.json_escape("hello") == "hello" + @test BazerUtils.json_escape("line1\nline2") == "line1\\nline2" + @test BazerUtils.json_escape("say \"hi\"") == "say \\\"hi\\\"" + @test BazerUtils.json_escape("back\\slash") == "back\\\\slash" + @test BazerUtils.json_escape("tab\there") == "tab\\there" + end + + @testset "logfmt_escape" begin + @test BazerUtils.logfmt_escape("simple") == "simple" + @test BazerUtils.logfmt_escape("has space") == "\"has space\"" + @test BazerUtils.logfmt_escape("has\"quote") == "\"has\\\"quote\"" + @test BazerUtils.logfmt_escape("has=equals") == "\"has=equals\"" + end + + @testset "FileSink" begin + tmp = tempname() + # Single file mode: deduplicates IO handles + sink = BazerUtils.FileSink(tmp; create_files=false) + @test length(sink.ios) == 4 + @test length(unique(objectid.(sink.ios))) == 1 # all same IO + @test length(sink.locks) == 4 + @test length(unique(objectid.(sink.locks))) == 1 # all same lock + @test all(io -> io !== stdout && io !== stderr, sink.ios) + close(sink) + rm(tmp, force=true) + + # Multi file mode: separate IO handles + sink2 = BazerUtils.FileSink(tmp; create_files=true) + @test length(sink2.ios) == 4 + @test length(unique(objectid.(sink2.ios))) == 4 # all different IO + @test length(unique(objectid.(sink2.locks))) == 4 # all different locks + close(sink2) + rm.(BazerUtils.get_log_filenames(tmp; create_files=true), force=true) + + # close guard: closing twice doesn't error + sink3 = BazerUtils.FileSink(tempname(); create_files=false) + close(sink3) + @test_nowarn close(sink3) # second close is safe + + # Count mismatch throws ArgumentError + @test_throws ArgumentError BazerUtils.get_log_filenames(["a.log", "b.log"]) + @test_throws ArgumentError BazerUtils.get_log_filenames(["a.log", "b.log", "c.log", "d.log", "e.log"]) + end + + @testset "format_log methods" begin + T = Dates.DateTime(2024, 1, 15, 14, 30, 0) + log_record = (level=Base.CoreLogging.Info, message="test message", + _module=BazerUtils, file="/src/app.jl", line=42, group=:test, id=:test) + nothing_record = (level=Base.CoreLogging.Info, message="nothing mod", + _module=nothing, file="test.jl", line=1, group=:test, id=:test) + + @testset "PrettyFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), log_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "test message") + @test contains(output, "14:30:00") + @test contains(output, "BazerUtils") + @test contains(output, "┌") + @test contains(output, "└") + end + + @testset "PrettyFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), nothing_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "unknown") + end + + @testset "OnelineFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), log_record, T; + displaysize=(50,100), shorten_path=:no) + output = String(take!(buf)) + @test contains(output, "INFO") + @test contains(output, "2024-01-15 14:30:00") + @test contains(output, "BazerUtils") + @test contains(output, "test message") + end + + @testset "OnelineFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), nothing_record, T; + displaysize=(50,100), shorten_path=:no) + output = String(take!(buf)) + @test contains(output, "unknown") + end + + @testset "SyslogFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), log_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "<14>") # facility=1, severity=6 -> (1*8)+6=14 + @test contains(output, "2024-01-15T14:30:00") + @test contains(output, "test message") + end + + @testset "SyslogFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), nothing_record, T; + displaysize=(50,100)) + output = String(take!(buf)) + @test contains(output, "nothing mod") + @test !contains(output, "nothing[") + end + + @testset "JsonFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.JsonFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test startswith(output, "{") + @test endswith(output, "}") + @test contains(output, "\"timestamp\":\"2024-01-15T14:30:00\"") + @test contains(output, "\"level\":\"INFO\"") + @test contains(output, "\"module\":\"BazerUtils\"") + @test contains(output, "\"message\":\"test message\"") + @test contains(output, "\"line\":42") + parsed = JSON.parse(output) + @test parsed["level"] == "INFO" + @test parsed["line"] == 42 + end + + @testset "JsonFormat escaping" begin + escape_record = (level=Base.CoreLogging.Warn, message="line1\nline2 \"quoted\"", + _module=nothing, file="test.jl", line=1, group=:test, id=:test) + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.JsonFormat(), escape_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + parsed = JSON.parse(output) + @test parsed["message"] == "line1\nline2 \"quoted\"" + @test parsed["module"] == "unknown" + end + + @testset "LogfmtFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "ts=2024-01-15T14:30:00") + @test contains(output, "level=info") + @test contains(output, "module=BazerUtils") + @test contains(output, "msg=\"test message\"") + end + + @testset "LogfmtFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), nothing_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "module=unknown") + end + + @testset "Log4jStandardFormat" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), log_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "2024-01-15 14:30:00,000") + @test contains(output, "INFO ") + @test contains(output, "BazerUtils") + @test contains(output, " - ") + @test contains(output, "test message") + end + + @testset "Log4jStandardFormat _module=nothing" begin + buf = IOBuffer() + BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), nothing_record, T; + displaysize=(50,100)) + output = strip(String(take!(buf))) + @test contains(output, "unknown") + @test contains(output, "nothing mod") + end + end + + # -- logger with everything in one place ... logger_single = custom_logger( log_path; - overwrite=true) + overwrite=true) @error "ERROR MESSAGE" @warn "WARN MESSAGE" @info "INFO MESSAGE" @@ -44,10 +242,10 @@ @test contains(log_content, "DEBUG MESSAGE") close_logger(logger_single, remove_files=true) - # -- logger across multiple files ... + # -- logger across multiple files ... logger_multiple = custom_logger( log_path; - overwrite=true, create_log_files=true) + overwrite=true, create_log_files=true) log_files = get_log_names(logger_multiple) @error "ERROR MESSAGE" @warn "WARN MESSAGE" @@ -96,8 +294,8 @@ # -- logger with formatting logger_single = custom_logger( log_path; - log_format=:log4j, - overwrite=true) + log_format=:oneline, + overwrite=true) @error "ERROR MESSAGE" @warn "WARN MESSAGE" @info "INFO MESSAGE" @@ -113,9 +311,9 @@ # -- logger with formatting and truncation logger_single = custom_logger( log_path; - log_format=:log4j, + log_format=:oneline, shorten_path=:truncate_middle, - overwrite=true) + overwrite=true) @error "ERROR MESSAGE" @warn "WARN MESSAGE" @info "INFO MESSAGE" @@ -136,7 +334,7 @@ log_path; log_format=:syslog, shorten_path=:truncate_middle, - overwrite=true) + overwrite=true) @error "ERROR MESSAGE" @warn "WARN MESSAGE" @info "INFO MESSAGE" @@ -145,7 +343,7 @@ log_file = get_log_names(logger_single)[1] log_content = read(log_file, String) # println(log_content) - # we should test for the lines + # we should test for the lines log_lines = split(log_content, "\n") @test all(map(contains("ERROR"), filter(contains("<11>"), log_lines))) @test all(map(contains("WARN"), filter(contains("<12>"), log_lines))) @@ -156,12 +354,13 @@ # -- logger with _module=nothing (issue #10) logger_single = custom_logger( log_path; - log_format=:log4j, + log_format=:oneline, overwrite=true) log_record = (level=Base.CoreLogging.Info, message="test nothing module", _module=nothing, file="test.jl", line=1, group=:test, id=:test) buf = IOBuffer() - BazerUtils.custom_format(buf, log_record; log_format=:log4j) + BazerUtils.custom_format(buf, BazerUtils.OnelineFormat(), log_record; + shorten_path=:no) output = String(take!(buf)) @test contains(output, "unknown") @test contains(output, "test nothing module") @@ -171,23 +370,158 @@ log_path = joinpath.(tempdir(), "log") logger_single = custom_logger( log_path; - create_log_files=true, overwrite=true, + create_log_files=true, overwrite=true, file_loggers = [:debug, :info]) @debug "DEBUG MESSAGE" @info "INFO MESSAGE" log_file = get_log_names(logger_single) log_content = read.(log_file, String) @test contains.(log_content, r"DEBUG .* DEBUG MESSAGE") == [true, false] - @test contains.(log_content, r"INFO .* INFO MESSAGE") == [true, true] + @test contains.(log_content, r"INFO .* INFO MESSAGE") == [false, true] close_logger(logger_single, remove_files=true) -end - + # -- exact level filtering (default: cascading_loglevels=false) + log_path_cl = joinpath(tempdir(), "log_cascading") + logger_exact = custom_logger( + log_path_cl; + overwrite=true, create_log_files=true) + @error "ONLY_ERROR" + @warn "ONLY_WARN" + @info "ONLY_INFO" + @debug "ONLY_DEBUG" + log_files_exact = get_log_names(logger_exact) + content_exact = read.(log_files_exact, String) + @test contains(content_exact[1], "ONLY_ERROR") + @test contains(content_exact[2], "ONLY_WARN") + @test contains(content_exact[3], "ONLY_INFO") + @test contains(content_exact[4], "ONLY_DEBUG") + @test !contains(content_exact[1], "ONLY_WARN") + @test !contains(content_exact[1], "ONLY_INFO") + @test !contains(content_exact[1], "ONLY_DEBUG") + @test !contains(content_exact[2], "ONLY_ERROR") + @test !contains(content_exact[2], "ONLY_INFO") + @test !contains(content_exact[2], "ONLY_DEBUG") + @test !contains(content_exact[3], "ONLY_ERROR") + @test !contains(content_exact[3], "ONLY_WARN") + @test !contains(content_exact[3], "ONLY_DEBUG") + @test !contains(content_exact[4], "ONLY_ERROR") + @test !contains(content_exact[4], "ONLY_WARN") + @test !contains(content_exact[4], "ONLY_INFO") + close_logger(logger_exact, remove_files=true) + # -- cascading level filtering (cascading_loglevels=true, old behavior) + logger_cascade = custom_logger( + log_path_cl; + overwrite=true, create_log_files=true, + cascading_loglevels=true) + @error "CASCADE_ERROR" + @warn "CASCADE_WARN" + @info "CASCADE_INFO" + @debug "CASCADE_DEBUG" + log_files_cascade = get_log_names(logger_cascade) + content_cascade = read.(log_files_cascade, String) + @test contains(content_cascade[1], "CASCADE_ERROR") + @test !contains(content_cascade[1], "CASCADE_WARN") + @test contains(content_cascade[2], "CASCADE_WARN") + @test contains(content_cascade[2], "CASCADE_ERROR") + @test contains(content_cascade[3], "CASCADE_INFO") + @test contains(content_cascade[3], "CASCADE_WARN") + @test contains(content_cascade[3], "CASCADE_ERROR") + @test contains(content_cascade[4], "CASCADE_DEBUG") + @test contains(content_cascade[4], "CASCADE_INFO") + @test contains(content_cascade[4], "CASCADE_WARN") + @test contains(content_cascade[4], "CASCADE_ERROR") + close_logger(logger_cascade, remove_files=true) + # -- JSON format logger + log_path_fmt = joinpath(tempdir(), "log_fmt") + logger_json = custom_logger( + log_path_fmt; + log_format=:json, overwrite=true) + @error "JSON_ERROR" + @info "JSON_INFO" + log_file_json = get_log_names(logger_json)[1] + json_lines = filter(!isempty, split(read(log_file_json, String), "\n")) + for line in json_lines + parsed = JSON.parse(line) + @test haskey(parsed, "timestamp") + @test haskey(parsed, "level") + @test haskey(parsed, "module") + @test haskey(parsed, "message") + end + close_logger(logger_json, remove_files=true) + # -- logfmt format logger + logger_logfmt = custom_logger( + log_path_fmt; + log_format=:logfmt, overwrite=true) + @error "LOGFMT_ERROR" + @info "LOGFMT_INFO" + log_file_logfmt = get_log_names(logger_logfmt)[1] + logfmt_content = read(log_file_logfmt, String) + @test contains(logfmt_content, "level=error") + @test contains(logfmt_content, "level=info") + @test contains(logfmt_content, r"ts=\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}") + @test contains(logfmt_content, "msg=") + close_logger(logger_logfmt, remove_files=true) + # -- log4j_standard format logger + logger_l4js = custom_logger( + log_path_fmt; + log_format=:log4j_standard, overwrite=true) + @error "L4JS_ERROR" + @info "L4JS_INFO" + log_file_l4js = get_log_names(logger_l4js)[1] + l4js_content = read(log_file_l4js, String) + @test contains(l4js_content, r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} ERROR") + @test contains(l4js_content, r"INFO .* - L4JS_INFO") + @test contains(l4js_content, " - ") + close_logger(logger_l4js, remove_files=true) + # -- unknown format throws + @test_throws ArgumentError custom_logger( + joinpath(tempdir(), "log_bad"); log_format=:banana, overwrite=true) + # -- :log4j deprecated alias still works + logger_deprecated = custom_logger( + log_path_fmt; + log_format=:log4j, overwrite=true) + @info "DEPRECATED_TEST" + log_file_dep = get_log_names(logger_deprecated)[1] + dep_content = read(log_file_dep, String) + @test contains(dep_content, "DEPRECATED_TEST") + close_logger(logger_deprecated, remove_files=true) + # -- thread safety: concurrent logging produces complete lines + log_path_thread = joinpath(tempdir(), "log_thread") + logger_thread = custom_logger( + log_path_thread; + log_format=:json, overwrite=true) + n_tasks = 10 + n_msgs = 50 + @sync for t in 1:n_tasks + Threads.@spawn begin + for m in 1:n_msgs + @info "task=$t msg=$m" + end + end + end + log_file_thread = get_log_names(logger_thread)[1] + # Flush all file streams + for lg in logger_thread.loggers + try + s = lg.logger.logger.stream + s isa IOStream && flush(s) + catch; end + end + thread_lines = filter(!isempty, split(read(log_file_thread, String), "\n")) + # Every line should be valid JSON (no interleaving) + for line in thread_lines + @test startswith(line, "{") + @test endswith(line, "}") + parsed = JSON.parse(line) + @test haskey(parsed, "message") + end + close_logger(logger_thread, remove_files=true) +end diff --git a/test/runtests.jl b/test/runtests.jl @@ -7,6 +7,7 @@ import LoggingExtras: ConsoleLogger, TeeLogger import JSON import CodecZlib import HTTP +import Dates const testsuite = [ "customlogger",