customlogger.jl (21274B)
1 @testset "CustomLogger" begin 2 3 function get_log_names(logger_in) 4 log_paths = map(l -> l.logger.logger.stream, logger_in.loggers) |> 5 (s -> filter(x -> x isa IOStream, s)) |> 6 (s -> map(x -> x.name, s)) |> 7 (s -> filter(x -> contains(x, "<file "), s)) |> 8 (s -> map(x -> match(r"<file (.+)>", x)[1], s)) 9 return unique(string.(log_paths)) 10 end 11 12 function close_logger(logger::TeeLogger; remove_files::Bool=false) 13 # Get filenames before closing 14 filenames = get_log_names(logger) 15 16 # Close all IOStreams 17 for min_logger in logger.loggers 18 stream = min_logger.logger.logger.stream 19 if stream isa IOStream 20 close(stream) 21 end 22 end 23 remove_files && rm.(filenames) # Optionally remove the files 24 25 # Reset to default logger 26 global_logger(ConsoleLogger(stderr)) 27 end 28 29 log_path = joinpath.(tempdir(), "log") 30 31 @testset "resolve_format" begin 32 @test BazerUtils.resolve_format(:pretty) isa BazerUtils.PrettyFormat 33 @test BazerUtils.resolve_format(:oneline) isa BazerUtils.OnelineFormat 34 @test BazerUtils.resolve_format(:syslog) isa BazerUtils.SyslogFormat 35 @test BazerUtils.resolve_format(:json) isa BazerUtils.JsonFormat 36 @test BazerUtils.resolve_format(:logfmt) isa BazerUtils.LogfmtFormat 37 @test BazerUtils.resolve_format(:log4j_standard) isa BazerUtils.Log4jStandardFormat 38 @test_throws ArgumentError BazerUtils.resolve_format(:invalid_format) 39 # :log4j is deprecated alias for :oneline 40 @test BazerUtils.resolve_format(:log4j) isa BazerUtils.OnelineFormat 41 end 42 43 @testset "get_module_name" begin 44 @test BazerUtils.get_module_name(nothing) == "unknown" 45 @test BazerUtils.get_module_name(Base) == "Base" 46 @test BazerUtils.get_module_name(Main) == "Main" 47 end 48 49 @testset "json_escape" begin 50 @test BazerUtils.json_escape("hello") == "hello" 51 @test BazerUtils.json_escape("line1\nline2") == "line1\\nline2" 52 @test BazerUtils.json_escape("say \"hi\"") == "say \\\"hi\\\"" 53 @test BazerUtils.json_escape("back\\slash") == "back\\\\slash" 54 @test BazerUtils.json_escape("tab\there") == "tab\\there" 55 end 56 57 @testset "logfmt_escape" begin 58 @test BazerUtils.logfmt_escape("simple") == "simple" 59 @test BazerUtils.logfmt_escape("has space") == "\"has space\"" 60 @test BazerUtils.logfmt_escape("has\"quote") == "\"has\\\"quote\"" 61 @test BazerUtils.logfmt_escape("has=equals") == "\"has=equals\"" 62 end 63 64 @testset "FileSink" begin 65 tmp = tempname() 66 # Single file mode: deduplicates IO handles 67 sink = BazerUtils.FileSink(tmp; create_files=false) 68 @test length(sink.ios) == 4 69 @test length(unique(objectid.(sink.ios))) == 1 # all same IO 70 @test length(sink.locks) == 4 71 @test length(unique(objectid.(sink.locks))) == 1 # all same lock 72 @test all(io -> io !== stdout && io !== stderr, sink.ios) 73 close(sink) 74 rm(tmp, force=true) 75 76 # Multi file mode: separate IO handles 77 sink2 = BazerUtils.FileSink(tmp; create_files=true) 78 @test length(sink2.ios) == 4 79 @test length(unique(objectid.(sink2.ios))) == 4 # all different IO 80 @test length(unique(objectid.(sink2.locks))) == 4 # all different locks 81 close(sink2) 82 rm.(BazerUtils.get_log_filenames(tmp; create_files=true), force=true) 83 84 # close guard: closing twice doesn't error 85 sink3 = BazerUtils.FileSink(tempname(); create_files=false) 86 close(sink3) 87 @test_nowarn close(sink3) # second close is safe 88 89 # Count mismatch throws ArgumentError 90 @test_throws ArgumentError BazerUtils.get_log_filenames(["a.log", "b.log"]) 91 @test_throws ArgumentError BazerUtils.get_log_filenames(["a.log", "b.log", "c.log", "d.log", "e.log"]) 92 end 93 94 @testset "format_log methods" begin 95 T = Dates.DateTime(2024, 1, 15, 14, 30, 0) 96 log_record = (level=Base.CoreLogging.Info, message="test message", 97 _module=BazerUtils, file="/src/app.jl", line=42, group=:test, id=:test) 98 nothing_record = (level=Base.CoreLogging.Info, message="nothing mod", 99 _module=nothing, file="test.jl", line=1, group=:test, id=:test) 100 101 @testset "PrettyFormat" begin 102 buf = IOBuffer() 103 BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), log_record, T; 104 displaysize=(50,100)) 105 output = String(take!(buf)) 106 @test contains(output, "test message") 107 @test contains(output, "14:30:00") 108 @test contains(output, "BazerUtils") 109 @test contains(output, "┌") 110 @test contains(output, "└") 111 end 112 113 @testset "PrettyFormat _module=nothing" begin 114 buf = IOBuffer() 115 BazerUtils.format_log(buf, BazerUtils.PrettyFormat(), nothing_record, T; 116 displaysize=(50,100)) 117 output = String(take!(buf)) 118 @test contains(output, "unknown") 119 end 120 121 @testset "OnelineFormat" begin 122 buf = IOBuffer() 123 BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), log_record, T; 124 displaysize=(50,100), shorten_path=:no) 125 output = String(take!(buf)) 126 @test contains(output, "INFO") 127 @test contains(output, "2024-01-15 14:30:00") 128 @test contains(output, "BazerUtils") 129 @test contains(output, "test message") 130 end 131 132 @testset "OnelineFormat _module=nothing" begin 133 buf = IOBuffer() 134 BazerUtils.format_log(buf, BazerUtils.OnelineFormat(), nothing_record, T; 135 displaysize=(50,100), shorten_path=:no) 136 output = String(take!(buf)) 137 @test contains(output, "unknown") 138 end 139 140 @testset "SyslogFormat" begin 141 buf = IOBuffer() 142 BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), log_record, T; 143 displaysize=(50,100)) 144 output = String(take!(buf)) 145 @test contains(output, "<14>") # facility=1, severity=6 -> (1*8)+6=14 146 @test contains(output, "2024-01-15T14:30:00") 147 @test contains(output, "test message") 148 end 149 150 @testset "SyslogFormat _module=nothing" begin 151 buf = IOBuffer() 152 BazerUtils.format_log(buf, BazerUtils.SyslogFormat(), nothing_record, T; 153 displaysize=(50,100)) 154 output = String(take!(buf)) 155 @test contains(output, "nothing mod") 156 @test !contains(output, "nothing[") 157 end 158 159 @testset "JsonFormat" begin 160 buf = IOBuffer() 161 BazerUtils.format_log(buf, BazerUtils.JsonFormat(), log_record, T; 162 displaysize=(50,100)) 163 output = strip(String(take!(buf))) 164 @test startswith(output, "{") 165 @test endswith(output, "}") 166 @test contains(output, "\"timestamp\":\"2024-01-15T14:30:00\"") 167 @test contains(output, "\"level\":\"INFO\"") 168 @test contains(output, "\"module\":\"BazerUtils\"") 169 @test contains(output, "\"message\":\"test message\"") 170 @test contains(output, "\"line\":42") 171 parsed = JSON.parse(output) 172 @test parsed["level"] == "INFO" 173 @test parsed["line"] == 42 174 end 175 176 @testset "JsonFormat escaping" begin 177 escape_record = (level=Base.CoreLogging.Warn, message="line1\nline2 \"quoted\"", 178 _module=nothing, file="test.jl", line=1, group=:test, id=:test) 179 buf = IOBuffer() 180 BazerUtils.format_log(buf, BazerUtils.JsonFormat(), escape_record, T; 181 displaysize=(50,100)) 182 output = strip(String(take!(buf))) 183 parsed = JSON.parse(output) 184 @test parsed["message"] == "line1\nline2 \"quoted\"" 185 @test parsed["module"] == "unknown" 186 end 187 188 @testset "LogfmtFormat" begin 189 buf = IOBuffer() 190 BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), log_record, T; 191 displaysize=(50,100)) 192 output = strip(String(take!(buf))) 193 @test contains(output, "ts=2024-01-15T14:30:00") 194 @test contains(output, "level=info") 195 @test contains(output, "module=BazerUtils") 196 @test contains(output, "msg=\"test message\"") 197 end 198 199 @testset "LogfmtFormat _module=nothing" begin 200 buf = IOBuffer() 201 BazerUtils.format_log(buf, BazerUtils.LogfmtFormat(), nothing_record, T; 202 displaysize=(50,100)) 203 output = strip(String(take!(buf))) 204 @test contains(output, "module=unknown") 205 end 206 207 @testset "Log4jStandardFormat" begin 208 buf = IOBuffer() 209 BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), log_record, T; 210 displaysize=(50,100)) 211 output = strip(String(take!(buf))) 212 @test contains(output, "2024-01-15 14:30:00,000") 213 @test contains(output, "INFO ") 214 @test contains(output, "BazerUtils") 215 @test contains(output, " - ") 216 @test contains(output, "test message") 217 end 218 219 @testset "Log4jStandardFormat _module=nothing" begin 220 buf = IOBuffer() 221 BazerUtils.format_log(buf, BazerUtils.Log4jStandardFormat(), nothing_record, T; 222 displaysize=(50,100)) 223 output = strip(String(take!(buf))) 224 @test contains(output, "unknown") 225 @test contains(output, "nothing mod") 226 end 227 end 228 229 # -- logger with everything in one place ... 230 logger_single = custom_logger( 231 log_path; 232 overwrite=true) 233 @error "ERROR MESSAGE" 234 @warn "WARN MESSAGE" 235 @info "INFO MESSAGE" 236 @debug "DEBUG MESSAGE" 237 log_file = get_log_names(logger_single)[1] 238 log_content = read(log_file, String) 239 @test contains(log_content, "ERROR MESSAGE") 240 @test contains(log_content, "WARN MESSAGE") 241 @test contains(log_content, "INFO MESSAGE") 242 @test contains(log_content, "DEBUG MESSAGE") 243 close_logger(logger_single, remove_files=true) 244 245 # -- logger across multiple files ... 246 logger_multiple = custom_logger( 247 log_path; 248 overwrite=true, create_log_files=true) 249 log_files = get_log_names(logger_multiple) 250 @error "ERROR MESSAGE" 251 @warn "WARN MESSAGE" 252 @info "INFO MESSAGE" 253 @debug "DEBUG MESSAGE" 254 log_content = read.(log_files, String) 255 @test contains(log_content[1], "ERROR MESSAGE") 256 @test contains(log_content[2], "WARN MESSAGE") 257 @test contains(log_content[3], "INFO MESSAGE") 258 @test contains(log_content[4], "DEBUG MESSAGE") 259 close_logger(logger_multiple, remove_files=true) 260 261 # -- logger with absolute filtering 262 logger_multiple = custom_logger( 263 log_path; 264 overwrite=true, create_log_files=true, 265 filtered_modules_all=[:HTTP], 266 ) ; 267 log_files = get_log_names(logger_multiple) 268 HTTP.get("http://example.com"); 269 log_content = read.(log_files, String) 270 @test countlines(log_files[1]) == 0 271 @test countlines(log_files[2]) == 0 272 @test countlines(log_files[3]) == 0 273 @test countlines(log_files[4]) != 0 # TranscodingStreams write here 274 @test !contains(log_content[4], r"HTTP"i) 275 close_logger(logger_multiple, remove_files=true) 276 277 # -- logger with specific filtering 278 logger_multiple = custom_logger( 279 log_path; 280 overwrite=true, create_log_files=true, 281 filtered_modules_specific=[:HTTP], 282 filtered_modules_all=[:TranscodingStreams], 283 ) ; 284 log_files = get_log_names(logger_multiple) 285 HTTP.get("http://example.com"); 286 log_content = read.(log_files, String) 287 @test countlines(log_files[1]) == 0 288 @test countlines(log_files[2]) == 0 289 @test countlines(log_files[3]) == 0; # this is getting filtered out 290 @test countlines(log_files[4]) != 0 # TranscodingStreams write here 291 @test contains(log_content[4], r"HTTP"i) 292 close_logger(logger_multiple, remove_files=true) 293 294 # -- logger with formatting 295 logger_single = custom_logger( 296 log_path; 297 log_format=:oneline, 298 overwrite=true) 299 @error "ERROR MESSAGE" 300 @warn "WARN MESSAGE" 301 @info "INFO MESSAGE" 302 @debug "DEBUG MESSAGE" 303 log_file = get_log_names(logger_single)[1] 304 log_content = read(log_file, String) 305 @test contains(log_content, r"ERROR .* ERROR MESSAGE") 306 @test contains(log_content, r"WARN .* WARN MESSAGE") 307 @test contains(log_content, r"INFO .* INFO MESSAGE") 308 @test contains(log_content, r"DEBUG .* DEBUG MESSAGE") 309 close_logger(logger_single, remove_files=true) 310 311 # -- logger with formatting and truncation 312 logger_single = custom_logger( 313 log_path; 314 log_format=:oneline, 315 shorten_path=:truncate_middle, 316 overwrite=true) 317 @error "ERROR MESSAGE" 318 @warn "WARN MESSAGE" 319 @info "INFO MESSAGE" 320 @debug "DEBUG MESSAGE" 321 HTTP.get("http://example.com"); 322 log_file = get_log_names(logger_single)[1] 323 log_content = read(log_file, String) 324 # println(log_content) 325 @test contains(log_content, r"ERROR .* ERROR MESSAGE") 326 @test contains(log_content, r"WARN .* WARN MESSAGE") 327 @test contains(log_content, r"INFO .* INFO MESSAGE") 328 @test contains(log_content, r"DEBUG .* DEBUG MESSAGE") 329 @test contains(log_content, "…") 330 close_logger(logger_single, remove_files=true) 331 332 # -- syslog logger 333 logger_single = custom_logger( 334 log_path; 335 log_format=:syslog, 336 shorten_path=:truncate_middle, 337 overwrite=true) 338 @error "ERROR MESSAGE" 339 @warn "WARN MESSAGE" 340 @info "INFO MESSAGE" 341 @debug "DEBUG MESSAGE" 342 HTTP.get("http://example.com"); 343 log_file = get_log_names(logger_single)[1] 344 log_content = read(log_file, String) 345 # println(log_content) 346 # we should test for the lines 347 log_lines = split(log_content, "\n") 348 @test all(map(contains("ERROR"), filter(contains("<11>"), log_lines))) 349 @test all(map(contains("WARN"), filter(contains("<12>"), log_lines))) 350 @test all(map(contains("INFO"), filter(contains("<14>"), log_lines))) 351 @test any(map(contains("DEBUG"), filter(contains("<15>"), log_lines))) 352 close_logger(logger_single, remove_files=true) 353 354 # -- logger with _module=nothing (issue #10) 355 logger_single = custom_logger( 356 log_path; 357 log_format=:oneline, 358 overwrite=true) 359 log_record = (level=Base.CoreLogging.Info, message="test nothing module", 360 _module=nothing, file="test.jl", line=1, group=:test, id=:test) 361 buf = IOBuffer() 362 BazerUtils.custom_format(buf, BazerUtils.OnelineFormat(), log_record; 363 shorten_path=:no) 364 output = String(take!(buf)) 365 @test contains(output, "unknown") 366 @test contains(output, "test nothing module") 367 close_logger(logger_single, remove_files=true) 368 369 # -- logger to only one file sink 370 log_path = joinpath.(tempdir(), "log") 371 logger_single = custom_logger( 372 log_path; 373 create_log_files=true, overwrite=true, 374 file_loggers = [:debug, :info]) 375 @debug "DEBUG MESSAGE" 376 @info "INFO MESSAGE" 377 log_file = get_log_names(logger_single) 378 log_content = read.(log_file, String) 379 @test contains.(log_content, r"DEBUG .* DEBUG MESSAGE") == [true, false] 380 @test contains.(log_content, r"INFO .* INFO MESSAGE") == [false, true] 381 close_logger(logger_single, remove_files=true) 382 383 # -- exact level filtering (default: cascading_loglevels=false) 384 log_path_cl = joinpath(tempdir(), "log_cascading") 385 logger_exact = custom_logger( 386 log_path_cl; 387 overwrite=true, create_log_files=true) 388 @error "ONLY_ERROR" 389 @warn "ONLY_WARN" 390 @info "ONLY_INFO" 391 @debug "ONLY_DEBUG" 392 log_files_exact = get_log_names(logger_exact) 393 content_exact = read.(log_files_exact, String) 394 @test contains(content_exact[1], "ONLY_ERROR") 395 @test contains(content_exact[2], "ONLY_WARN") 396 @test contains(content_exact[3], "ONLY_INFO") 397 @test contains(content_exact[4], "ONLY_DEBUG") 398 @test !contains(content_exact[1], "ONLY_WARN") 399 @test !contains(content_exact[1], "ONLY_INFO") 400 @test !contains(content_exact[1], "ONLY_DEBUG") 401 @test !contains(content_exact[2], "ONLY_ERROR") 402 @test !contains(content_exact[2], "ONLY_INFO") 403 @test !contains(content_exact[2], "ONLY_DEBUG") 404 @test !contains(content_exact[3], "ONLY_ERROR") 405 @test !contains(content_exact[3], "ONLY_WARN") 406 @test !contains(content_exact[3], "ONLY_DEBUG") 407 @test !contains(content_exact[4], "ONLY_ERROR") 408 @test !contains(content_exact[4], "ONLY_WARN") 409 @test !contains(content_exact[4], "ONLY_INFO") 410 close_logger(logger_exact, remove_files=true) 411 412 # -- cascading level filtering (cascading_loglevels=true, old behavior) 413 logger_cascade = custom_logger( 414 log_path_cl; 415 overwrite=true, create_log_files=true, 416 cascading_loglevels=true) 417 @error "CASCADE_ERROR" 418 @warn "CASCADE_WARN" 419 @info "CASCADE_INFO" 420 @debug "CASCADE_DEBUG" 421 log_files_cascade = get_log_names(logger_cascade) 422 content_cascade = read.(log_files_cascade, String) 423 @test contains(content_cascade[1], "CASCADE_ERROR") 424 @test !contains(content_cascade[1], "CASCADE_WARN") 425 @test contains(content_cascade[2], "CASCADE_WARN") 426 @test contains(content_cascade[2], "CASCADE_ERROR") 427 @test contains(content_cascade[3], "CASCADE_INFO") 428 @test contains(content_cascade[3], "CASCADE_WARN") 429 @test contains(content_cascade[3], "CASCADE_ERROR") 430 @test contains(content_cascade[4], "CASCADE_DEBUG") 431 @test contains(content_cascade[4], "CASCADE_INFO") 432 @test contains(content_cascade[4], "CASCADE_WARN") 433 @test contains(content_cascade[4], "CASCADE_ERROR") 434 close_logger(logger_cascade, remove_files=true) 435 436 # -- JSON format logger 437 log_path_fmt = joinpath(tempdir(), "log_fmt") 438 logger_json = custom_logger( 439 log_path_fmt; 440 log_format=:json, overwrite=true) 441 @error "JSON_ERROR" 442 @info "JSON_INFO" 443 log_file_json = get_log_names(logger_json)[1] 444 json_lines = filter(!isempty, split(read(log_file_json, String), "\n")) 445 for line in json_lines 446 parsed = JSON.parse(line) 447 @test haskey(parsed, "timestamp") 448 @test haskey(parsed, "level") 449 @test haskey(parsed, "module") 450 @test haskey(parsed, "message") 451 end 452 close_logger(logger_json, remove_files=true) 453 454 # -- logfmt format logger 455 logger_logfmt = custom_logger( 456 log_path_fmt; 457 log_format=:logfmt, overwrite=true) 458 @error "LOGFMT_ERROR" 459 @info "LOGFMT_INFO" 460 log_file_logfmt = get_log_names(logger_logfmt)[1] 461 logfmt_content = read(log_file_logfmt, String) 462 @test contains(logfmt_content, "level=error") 463 @test contains(logfmt_content, "level=info") 464 @test contains(logfmt_content, r"ts=\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}") 465 @test contains(logfmt_content, "msg=") 466 close_logger(logger_logfmt, remove_files=true) 467 468 # -- log4j_standard format logger 469 logger_l4js = custom_logger( 470 log_path_fmt; 471 log_format=:log4j_standard, overwrite=true) 472 @error "L4JS_ERROR" 473 @info "L4JS_INFO" 474 log_file_l4js = get_log_names(logger_l4js)[1] 475 l4js_content = read(log_file_l4js, String) 476 @test contains(l4js_content, r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} ERROR") 477 @test contains(l4js_content, r"INFO .* - L4JS_INFO") 478 @test contains(l4js_content, " - ") 479 close_logger(logger_l4js, remove_files=true) 480 481 # -- unknown format throws 482 @test_throws ArgumentError custom_logger( 483 joinpath(tempdir(), "log_bad"); log_format=:banana, overwrite=true) 484 485 # -- :log4j deprecated alias still works 486 logger_deprecated = custom_logger( 487 log_path_fmt; 488 log_format=:log4j, overwrite=true) 489 @info "DEPRECATED_TEST" 490 log_file_dep = get_log_names(logger_deprecated)[1] 491 dep_content = read(log_file_dep, String) 492 @test contains(dep_content, "DEPRECATED_TEST") 493 close_logger(logger_deprecated, remove_files=true) 494 495 # -- thread safety: concurrent logging produces complete lines 496 log_path_thread = joinpath(tempdir(), "log_thread") 497 logger_thread = custom_logger( 498 log_path_thread; 499 log_format=:json, overwrite=true) 500 n_tasks = 10 501 n_msgs = 50 502 @sync for t in 1:n_tasks 503 Threads.@spawn begin 504 for m in 1:n_msgs 505 @info "task=$t msg=$m" 506 end 507 end 508 end 509 log_file_thread = get_log_names(logger_thread)[1] 510 # Flush all file streams 511 for lg in logger_thread.loggers 512 try 513 s = lg.logger.logger.stream 514 s isa IOStream && flush(s) 515 catch; end 516 end 517 thread_lines = filter(!isempty, split(read(log_file_thread, String), "\n")) 518 # Every line should be valid JSON (no interleaving) 519 for line in thread_lines 520 @test startswith(line, "{") 521 @test endswith(line, "}") 522 parsed = JSON.parse(line) 523 @test haskey(parsed, "message") 524 end 525 close_logger(logger_thread, remove_files=true) 526 527 end