StatProfilerHTML.jl report
Generated on Thu, 21 Dec 2023 13:06:16
File source code
Line Exclusive Inclusive Code
1 # This file is a part of Julia. License is MIT: https://julialang.org/license
2
3 module CoreLogging
4
5 import Base: isless, +, -, convert, show
6
7 export
8 AbstractLogger,
9 LogLevel,
10 NullLogger,
11 @debug,
12 @info,
13 @warn,
14 @error,
15 @logmsg,
16 with_logger,
17 current_logger,
18 global_logger,
19 disable_logging,
20 SimpleLogger
21
22 #-------------------------------------------------------------------------------
23 # The AbstractLogger interface
24 """
25 A logger controls how log records are filtered and dispatched. When a log
26 record is generated, the logger is the first piece of user configurable code
27 which gets to inspect the record and decide what to do with it.
28 """
29 abstract type AbstractLogger ; end
30
31 """
32 handle_message(logger, level, message, _module, group, id, file, line; key1=val1, ...)
33
34 Log a message to `logger` at `level`. The logical location at which the
35 message was generated is given by module `_module` and `group`; the source
36 location by `file` and `line`. `id` is an arbitrary unique value (typically a
37 [`Symbol`](@ref)) to be used as a key to identify the log statement when
38 filtering.
39 """
40 function handle_message end
41
42 """
43 shouldlog(logger, level, _module, group, id)
44
45 Return `true` when `logger` accepts a message at `level`, generated for
46 `_module`, `group` and with unique log identifier `id`.
47 """
48 function shouldlog end
49
50 """
51 min_enabled_level(logger)
52
53 Return the minimum enabled level for `logger` for early filtering. That is,
54 the log level below or equal to which all messages are filtered.
55 """
56 function min_enabled_level end
57
58 """
59 catch_exceptions(logger)
60
61 Return `true` if the logger should catch exceptions which happen during log
62 record construction. By default, messages are caught
63
64 By default all exceptions are caught to prevent log message generation from
65 crashing the program. This lets users confidently toggle little-used
66 functionality - such as debug logging - in a production system.
67
68 If you want to use logging as an audit trail you should disable this for your
69 logger type.
70 """
71 catch_exceptions(logger) = true
72
73
74 # Prevent invalidation when packages define custom loggers
75 # Using invoke in combination with @nospecialize eliminates backedges to these methods
76 Base.@constprop :none function _invoked_shouldlog(logger, level, _module, group, id)
77 @nospecialize
78 return invoke(
79 shouldlog,
80 Tuple{typeof(logger), typeof(level), typeof(_module), typeof(group), typeof(id)},
81 logger, level, _module, group, id
82 )::Bool
83 end
84
85 function _invoked_min_enabled_level(@nospecialize(logger))
86 return invoke(min_enabled_level, Tuple{typeof(logger)}, logger)::LogLevel
87 end
88
89 function _invoked_catch_exceptions(@nospecialize(logger))
90 return invoke(catch_exceptions, Tuple{typeof(logger)}, logger)::Bool
91 end
92
93 """
94 NullLogger()
95
96 Logger which disables all messages and produces no output - the logger
97 equivalent of /dev/null.
98 """
99 struct NullLogger <: AbstractLogger; end
100
101 min_enabled_level(::NullLogger) = AboveMaxLevel
102 shouldlog(::NullLogger, args...) = false
103 handle_message(::NullLogger, args...; kwargs...) =
104 (@nospecialize; error("Null logger handle_message() should not be called"))
105
106
107 #-------------------------------------------------------------------------------
108 # Standard log levels
109 """
110 LogLevel(level)
111
112 Severity/verbosity of a log record.
113
114 The log level provides a key against which potential log records may be
115 filtered, before any other work is done to construct the log record data
116 structure itself.
117
118 # Examples
119 ```julia-repl
120 julia> Logging.LogLevel(0) == Logging.Info
121 true
122 ```
123 """
124 struct LogLevel
125 level::Int32
126 end
127
128 LogLevel(level::LogLevel) = level
129
130 isless(a::LogLevel, b::LogLevel) = isless(a.level, b.level)
131 +(level::LogLevel, inc::Integer) = LogLevel(level.level+inc)
132 -(level::LogLevel, inc::Integer) = LogLevel(level.level-inc)
133 convert(::Type{LogLevel}, level::Integer) = LogLevel(level)
134
135 const BelowMinLevel = LogLevel(-1000001)
136 """
137 Debug
138
139 Alias for [`LogLevel(-1000)`](@ref LogLevel).
140 """
141 const Debug = LogLevel( -1000)
142 """
143 Info
144
145 Alias for [`LogLevel(0)`](@ref LogLevel).
146 """
147 const Info = LogLevel( 0)
148 """
149 Warn
150
151 Alias for [`LogLevel(1000)`](@ref LogLevel).
152 """
153 const Warn = LogLevel( 1000)
154 """
155 Error
156
157 Alias for [`LogLevel(2000)`](@ref LogLevel).
158 """
159 const Error = LogLevel( 2000)
160 const AboveMaxLevel = LogLevel( 1000001)
161
162 # Global log limiting mechanism for super fast but inflexible global log limiting.
163 const _min_enabled_level = Ref{LogLevel}(Debug)
164
165 function show(io::IO, level::LogLevel)
166 if level == BelowMinLevel print(io, "BelowMinLevel")
167 elseif level == Debug print(io, "Debug")
168 elseif level == Info print(io, "Info")
169 elseif level == Warn print(io, "Warn")
170 elseif level == Error print(io, "Error")
171 elseif level == AboveMaxLevel print(io, "AboveMaxLevel")
172 else print(io, "LogLevel($(level.level))")
173 end
174 end
175
176
177 #-------------------------------------------------------------------------------
178 # Logging macros
179
180 _logmsg_docs = """
181 @debug message [key=value | value ...]
182 @info message [key=value | value ...]
183 @warn message [key=value | value ...]
184 @error message [key=value | value ...]
185
186 @logmsg level message [key=value | value ...]
187
188 Create a log record with an informational `message`. For convenience, four
189 logging macros `@debug`, `@info`, `@warn` and `@error` are defined which log at
190 the standard severity levels `Debug`, `Info`, `Warn` and `Error`. `@logmsg`
191 allows `level` to be set programmatically to any `LogLevel` or custom log level
192 types.
193
194 `message` should be an expression which evaluates to a string which is a human
195 readable description of the log event. By convention, this string will be
196 formatted as markdown when presented.
197
198 The optional list of `key=value` pairs supports arbitrary user defined
199 metadata which will be passed through to the logging backend as part of the
200 log record. If only a `value` expression is supplied, a key representing the
201 expression will be generated using [`Symbol`](@ref). For example, `x` becomes `x=x`,
202 and `foo(10)` becomes `Symbol("foo(10)")=foo(10)`. For splatting a list of
203 key value pairs, use the normal splatting syntax, `@info "blah" kws...`.
204
205 There are some keys which allow automatically generated log data to be
206 overridden:
207
208 * `_module=mod` can be used to specify a different originating module from
209 the source location of the message.
210 * `_group=symbol` can be used to override the message group (this is
211 normally derived from the base name of the source file).
212 * `_id=symbol` can be used to override the automatically generated unique
213 message identifier. This is useful if you need to very closely associate
214 messages generated on different source lines.
215 * `_file=string` and `_line=integer` can be used to override the apparent
216 source location of a log message.
217
218 There's also some key value pairs which have conventional meaning:
219
220 * `maxlog=integer` should be used as a hint to the backend that the message
221 should be displayed no more than `maxlog` times.
222 * `exception=ex` should be used to transport an exception with a log message,
223 often used with `@error`. An associated backtrace `bt` may be attached
224 using the tuple `exception=(ex,bt)`.
225
226 # Examples
227
228 ```julia
229 @debug "Verbose debugging information. Invisible by default"
230 @info "An informational message"
231 @warn "Something was odd. You should pay attention"
232 @error "A non fatal error occurred"
233
234 x = 10
235 @info "Some variables attached to the message" x a=42.0
236
237 @debug begin
238 sA = sum(A)
239 "sum(A) = \$sA is an expensive operation, evaluated only when `shouldlog` returns true"
240 end
241
242 for i=1:10000
243 @info "With the default backend, you will only see (i = \$i) ten times" maxlog=10
244 @debug "Algorithm1" i progress=i/10000
245 end
246 ```
247 """
248
249 # Get (module,filepath,line) for the location of the caller of a macro.
250 # Designed to be used from within the body of a macro.
251 macro _sourceinfo()
252 esc(quote
253 (__module__,
254 __source__.file === nothing ? "?" : String(__source__.file::Symbol),
255 __source__.line)
256 end)
257 end
258
259 macro logmsg(level, exs...) logmsg_code((@_sourceinfo)..., esc(level), exs...) end
260 macro debug(exs...) logmsg_code((@_sourceinfo)..., :Debug, exs...) end
261 macro info(exs...) logmsg_code((@_sourceinfo)..., :Info, exs...) end
262 macro warn(exs...) logmsg_code((@_sourceinfo)..., :Warn, exs...) end
263 macro error(exs...) logmsg_code((@_sourceinfo)..., :Error, exs...) end
264
265 # Logging macros share documentation
266 @eval @doc $_logmsg_docs :(@logmsg)
267 @eval @doc $_logmsg_docs :(@debug)
268 @eval @doc $_logmsg_docs :(@info)
269 @eval @doc $_logmsg_docs :(@warn)
270 @eval @doc $_logmsg_docs :(@error)
271
272 _log_record_ids = Set{Symbol}()
273 # Generate a unique, stable, short, somewhat human readable identifier for a
274 # logging *statement*. The idea here is to have a key against which log events
275 # can be filtered and otherwise manipulated. The key should uniquely identify
276 # the source location in the originating module, but ideally should be stable
277 # across versions of the originating module, provided the log generating
278 # statement itself doesn't change.
279 function log_record_id(_module, level, message, log_kws)
280 @nospecialize
281 modname = _module === nothing ? "" : join(fullname(_module), "_")
282 # Use an arbitrarily chosen eight hex digits here. TODO: Figure out how to
283 # make the id exactly the same on 32 and 64 bit systems.
284 h = UInt32(hash(string(modname, level, message, log_kws)::String) & 0xFFFFFFFF)
285 while true
286 id = Symbol(modname, '_', string(h, base = 16, pad = 8))
287 # _log_record_ids is a registry of log record ids for use during
288 # compilation, to ensure uniqueness of ids. Note that this state will
289 # only persist during module compilation so it will be empty when a
290 # precompiled module is loaded.
291 if !(id in _log_record_ids)
292 push!(_log_record_ids, id)
293 return id
294 end
295 h += 1
296 end
297 end
298
299 default_group(file) = Symbol(splitext(basename(file))[1])
300
301 function issimple(@nospecialize val)
302 val isa String && return true
303 val isa Symbol && return true
304 val isa QuoteNode && return true
305 val isa Number && return true
306 val isa Char && return true
307 if val isa Expr
308 val.head === :quote && issimple(val.args[1]) && return true
309 val.head === :inert && return true
310 end
311 return false
312 end
313 function issimplekw(@nospecialize val)
314 if val isa Expr
315 if val.head === :kw
316 val = val.args[2]
317 if val isa Expr && val.head === :escape
318 issimple(val.args[1]) && return true
319 end
320 end
321 end
322 return false
323 end
324
325 # helper function to get the current logger, if enabled for the specified message type
326 @noinline Base.@constprop :none function current_logger_for_env(std_level::LogLevel, group, _module)
327 logstate = @inline current_logstate()
328 if std_level >= logstate.min_enabled_level || env_override_minlevel(group, _module)
329 return logstate.logger
330 end
331 return nothing
332 end
333
334 # Generate code for logging macros
335 function logmsg_code(_module, file, line, level, message, exs...)
336 @nospecialize
337 log_data = process_logmsg_exs(_module, file, line, level, message, exs...)
338 if !isa(message, Symbol) && issimple(message) && isempty(log_data.kwargs)
339 logrecord = quote
340 msg = $(message)
341 kwargs = (;)
342 true
343 end
344 elseif issimple(message) && all(issimplekw, log_data.kwargs)
345 # if message and kwargs are just values and variables, we can avoid try/catch
346 # complexity by adding the code for testing the UndefVarError by hand
347 checkerrors = nothing
348 for kwarg in reverse(log_data.kwargs)
349 if isa(kwarg.args[2].args[1], Symbol)
350 checkerrors = Expr(:if, Expr(:isdefined, kwarg.args[2]), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(kwarg.args[2].args[1])))
351 end
352 end
353 if isa(message, Symbol)
354 message = esc(message)
355 checkerrors = Expr(:if, Expr(:isdefined, message), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(message.args[1])))
356 end
357 logrecord = quote
358 let err = $checkerrors
359 if err === nothing
360 msg = $(message)
361 kwargs = (;$(log_data.kwargs...))
362 true
363 else
364 @invokelatest logging_error(logger, level, _module, group, id, file, line, err, false)
365 false
366 end
367 end
368 end
369 else
370 logrecord = quote
371 try
372 msg = $(esc(message))
373 kwargs = (;$(log_data.kwargs...))
374 true
375 catch err
376 @invokelatest logging_error(logger, level, _module, group, id, file, line, err, true)
377 false
378 end
379 end
380 end
381 return quote
382 let
383 level = $level
384 # simplify std_level code emitted, if we know it is one of our global constants
385 std_level = $(level isa Symbol ? :level : :(level isa $LogLevel ? level : convert($LogLevel, level)::$LogLevel))
386 if std_level >= $(_min_enabled_level)[]
387 group = $(log_data._group)
388 _module = $(log_data._module)
389 logger = $(current_logger_for_env)(std_level, group, _module)
390 if !(logger === nothing)
391 id = $(log_data._id)
392 # Second chance at an early bail-out (before computing the message),
393 # based on arbitrary logger-specific logic.
394 if invokelatest($shouldlog, logger, level, _module, group, id)
395 file = $(log_data._file)
396 if file isa String
397 file = Base.fixup_stdlib_path(file)
398 end
399 line = $(log_data._line)
400 local msg, kwargs
401 $(logrecord) && invokelatest($handle_message,
402 logger, level, msg, _module, group, id, file, line;
403 kwargs...)
404 end
405 end
406 end
407 nothing
408 end
409 end
410 end
411
412 function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
413 @nospecialize
414 local _group, _id
415 _module = _orig_module
416 kwargs = Any[]
417 for ex in exs
418 if ex isa Expr && ex.head === :(=)
419 k, v = ex.args
420 if !(k isa Symbol)
421 k = Symbol(k)
422 end
423
424 # Recognize several special keyword arguments
425 if k === :_group
426 _group = esc(v)
427 elseif k === :_id
428 _id = esc(v)
429 elseif k === :_module
430 _module = esc(v)
431 elseif k === :_file
432 _file = esc(v)
433 elseif k === :_line
434 _line = esc(v)
435 else
436 # Copy across key value pairs for structured log records
437 push!(kwargs, Expr(:kw, k, esc(v)))
438 end
439 elseif ex isa Expr && ex.head === :... # Keyword splatting
440 push!(kwargs, esc(ex))
441 else # Positional arguments - will be converted to key value pairs automatically.
442 push!(kwargs, Expr(:kw, Symbol(ex), esc(ex)))
443 end
444 end
445
446 if !@isdefined(_group)
447 _group = default_group_code(_file)
448 end
449 if !@isdefined(_id)
450 _id = Expr(:quote, log_record_id(_orig_module, level, message, exs))
451 end
452 return (;_module, _group, _id, _file, _line, kwargs)
453 end
454
455 function default_group_code(file)
456 @nospecialize
457 if file isa String && isdefined(Base, :basename)
458 QuoteNode(default_group(file)) # precompute if we can
459 else
460 ref = Ref{Symbol}() # memoized run-time execution
461 :(isassigned($ref) ? $ref[] : $ref[] = default_group(something($file, ""))::Symbol)
462 end
463 end
464
465
466 # Report an error in log message creation
467 @noinline function logging_error(logger, level, _module, group, id,
468 filepath, line, @nospecialize(err), real::Bool)
469 @nospecialize
470 if !_invoked_catch_exceptions(logger)
471 real ? rethrow(err) : throw(err)
472 end
473 msg = try
474 "Exception while generating log record in module $_module at $filepath:$line"
475 catch ex
476 LazyString("Exception handling log message: ", ex)
477 end
478 bt = real ? catch_backtrace() : backtrace()
479 handle_message(
480 logger, Error, msg, _module, :logevent_error, id, filepath, line;
481 exception=(err,bt))
482 nothing
483 end
484
485 # Log a message. Called from the julia C code; kwargs is in the format
486 # Any[key1,val1, ...] for simplicity in construction on the C side.
487 function logmsg_shim(level, message, _module, group, id, file, line, kwargs)
488 @nospecialize
489 real_kws = Any[(kwargs[i], kwargs[i+1]) for i in 1:2:length(kwargs)]
490 @logmsg(convert(LogLevel, level), message,
491 _module=_module, _id=id, _group=group,
492 _file=String(file), _line=line, real_kws...)
493 nothing
494 end
495
496 # LogState - a cache of data extracted from the logger, plus the logger itself.
497 struct LogState
498 min_enabled_level::LogLevel
499 logger::AbstractLogger
500 end
501
502 LogState(logger) = LogState(LogLevel(_invoked_min_enabled_level(logger)), logger)
503
504 function current_logstate()
505 logstate = current_task().logstate
506 return (logstate !== nothing ? logstate : _global_logstate)::LogState
507 end
508
509
272 (100 %) samples spent in with_logstate
272 (100 %) (incl.) when called from with_logger line 627
function with_logstate(f::Function, logstate)
510 @nospecialize
511 t = current_task()
512 old = t.logstate
513 try
514 t.logstate = logstate
515 272 (100 %)
272 (100 %) samples spent calling #65
f()
516 finally
517 t.logstate = old
518 end
519 end
520
521 #-------------------------------------------------------------------------------
522 # Control of the current logger and early log filtering
523
524 """
525 disable_logging(level)
526
527 Disable all log messages at log levels equal to or less than `level`. This is
528 a *global* setting, intended to make debug logging extremely cheap when
529 disabled.
530
531 # Examples
532 ```julia
533 Logging.disable_logging(Logging.Info) # Disable debug and info
534 ```
535 """
536 function disable_logging(level::LogLevel)
537 _min_enabled_level[] = level + 1
538 end
539
540 let _debug_groups_include::Vector{Symbol} = Symbol[],
541 _debug_groups_exclude::Vector{Symbol} = Symbol[],
542 _debug_str::String = ""
543 global Base.@constprop :none function env_override_minlevel(group, _module)
544 debug = get(ENV, "JULIA_DEBUG", "")
545 if !(debug === _debug_str)
546 _debug_str = debug
547 empty!(_debug_groups_include)
548 empty!(_debug_groups_exclude)
549 for g in split(debug, ',')
550 if !isempty(g)
551 if startswith(g, "!")
552 if !isempty(g[2:end])
553 push!(_debug_groups_exclude, Symbol(g[2:end]))
554 end
555 else
556 push!(_debug_groups_include, Symbol(g))
557 end
558 end
559 end
560 unique!(_debug_groups_include)
561 unique!(_debug_groups_exclude)
562 end
563
564 if !(:all in _debug_groups_exclude) && (:all in _debug_groups_include || !isempty(_debug_groups_exclude))
565 if isempty(_debug_groups_exclude)
566 return true
567 elseif isa(group, Symbol) && group in _debug_groups_exclude
568 return false
569 elseif isa(_module, Module) && (nameof(_module) in _debug_groups_exclude || nameof(Base.moduleroot(_module)) in _debug_groups_exclude)
570 return false
571 else
572 return true
573 end
574 else
575 if isempty(_debug_groups_include)
576 return false
577 elseif isa(group, Symbol) && group in _debug_groups_include
578 return true
579 elseif isa(_module, Module) && (nameof(_module) in _debug_groups_include || nameof(Base.moduleroot(_module)) in _debug_groups_include)
580 return true
581 else
582 return false
583 end
584 end
585 return false
586 end
587 end
588
589
590 """
591 global_logger()
592
593 Return the global logger, used to receive messages when no specific logger
594 exists for the current task.
595
596 global_logger(logger)
597
598 Set the global logger to `logger`, and return the previous global logger.
599 """
600 global_logger() = _global_logstate.logger
601
602 function global_logger(logger::AbstractLogger)
603 prev = _global_logstate.logger
604 global _global_logstate = LogState(logger)
605 prev
606 end
607
608 """
609 with_logger(function, logger)
610
611 Execute `function`, directing all log messages to `logger`.
612
613 # Example
614
615 ```julia
616 function test(x)
617 @info "x = \$x"
618 end
619
620 with_logger(logger) do
621 test(1)
622 test([1,2])
623 end
624 ```
625 """
626 function with_logger(@nospecialize(f::Function), logger::AbstractLogger)
627 272 (100 %)
272 (100 %) samples spent in with_logger
272 (100 %) (incl.) when called from #64 line 255
272 (100 %) samples spent calling with_logstate
with_logstate(f, LogState(logger))
628 end
629
630 """
631 current_logger()
632
633 Return the logger for the current task, or the global logger if none is
634 attached to the task.
635 """
636 current_logger() = current_logstate().logger
637
638 const closed_stream = IOBuffer(UInt8[])
639 close(closed_stream)
640
641 #-------------------------------------------------------------------------------
642 # SimpleLogger
643 """
644 SimpleLogger([stream,] min_level=Info)
645
646 Simplistic logger for logging all messages with level greater than or equal to
647 `min_level` to `stream`. If stream is closed then messages with log level
648 greater or equal to `Warn` will be logged to `stderr` and below to `stdout`.
649 """
650 struct SimpleLogger <: AbstractLogger
651 stream::IO
652 min_level::LogLevel
653 message_limits::Dict{Any,Int}
654 end
655 SimpleLogger(stream::IO, level=Info) = SimpleLogger(stream, level, Dict{Any,Int}())
656 SimpleLogger(level=Info) = SimpleLogger(closed_stream, level)
657
658 shouldlog(logger::SimpleLogger, level, _module, group, id) =
659 get(logger.message_limits, id, 1) > 0
660
661 min_enabled_level(logger::SimpleLogger) = logger.min_level
662
663 catch_exceptions(logger::SimpleLogger) = false
664
665 function handle_message(logger::SimpleLogger, level::LogLevel, message, _module, group, id,
666 filepath, line; kwargs...)
667 @nospecialize
668 maxlog = get(kwargs, :maxlog, nothing)
669 if maxlog isa Core.BuiltinInts
670 remaining = get!(logger.message_limits, id, Int(maxlog)::Int)
671 logger.message_limits[id] = remaining - 1
672 remaining > 0 || return
673 end
674 buf = IOBuffer()
675 stream::IO = logger.stream
676 if !(isopen(stream)::Bool)
677 stream = stderr
678 end
679 iob = IOContext(buf, stream)
680 levelstr = level == Warn ? "Warning" : string(level)
681 msglines = eachsplit(chomp(convert(String, string(message))::String), '\n')
682 msg1, rest = Iterators.peel(msglines)
683 println(iob, "┌ ", levelstr, ": ", msg1)
684 for msg in rest
685 println(iob, "│ ", msg)
686 end
687 for (key, val) in kwargs
688 key === :maxlog && continue
689 println(iob, "│ ", key, " = ", val)
690 end
691 println(iob, "└ @ ", _module, " ", filepath, ":", line)
692 write(stream, take!(buf))
693 nothing
694 end
695
696 _global_logstate = LogState(SimpleLogger())
697
698 end # CoreLogging