Ведение журнала

Модуль Logging предоставляет способ записи истории и хода вычислений в виде журнала событий. События создаются путем вставки оператора ведения журнала в исходный код, например:

@warn "Abandon printf debugging, all ye who enter here!"
┌ Warning: Abandon printf debugging, all ye who enter here!
└ @ Main REPL[1]:1

Система предоставляет несколько преимуществ по сравнению с вставкой вызовов println() в исходный код. Во-первых, она позволяет управлять видимостью и представлением сообщений без редактирования исходного кода. Например, в отличие от @warn выше

@debug "The sum of some values $(sum(rand(100)))"

по умолчанию не будет выводить ничего на экран. Кроме того, оставление отладочных инструкций такого рода в исходном коде очень дешево, потому что система избегает вычисления сообщения, если оно впоследствии будет проигнорировано. В этом случае sum(rand(100)) и связанная с ним обработка строк никогда не будут выполнены, если отладочное ведение журнала не включено.

Во-вторых, инструменты ведения журнала позволяют присоединять произвольные данные к каждому событию в виде набора пар «ключ-значение». Это позволяет захватывать локальные переменные и другие состояния программы для последующего анализа. Например, для присоединения локальной переменной массива A и суммы вектора v в качестве ключа s можно использовать

A = ones(Int, 4, 4)
v = ones(100)
@info "Some variables"  A  s=sum(v)

# output
┌ Info: Some variables
│   A =
│    4×4 Matrix{Int64}:
│     1  1  1  1
│     1  1  1  1
│     1  1  1  1
│     1  1  1  1
└   s = 100.0

Все макросы ведения журнала @debug, @info, @warn и @error имеют общие характеристики, подробно описанные в документации для более общего макроса @logmsg.

Структура события журнала

Каждое событие генерирует несколько данных, некоторые из которых задаются пользователем, а некоторые извлекаются автоматически. Сначала рассмотрим пользовательские данные:

• Уровень журнала — это широкая категория для сообщения, используемая для ранней фильтрации. Существует несколько стандартных уровней типа LogLevel; также возможны пользовательские уровни. Каждый из них имеет определенную цель:

  • Logging.Debug (уровень журнала -1000) — это информация, предназначенная для разработчика программы. Эти события отключены по умолчанию.
  • Logging.Info (уровень журнала 0) — это общая информация для пользователя. Представьте себе, как альтернатива использованию println напрямую.
  • Logging.Warn (уровень журнала 1000) означает, что что-то не так, и, скорее всего, потребуется действие, но пока программа всё ещё работает.
  • Logging.Error (уровень журнала 2000) означает, что что-то не так, и маловероятно, что это удастся исправить, по крайней мере, этой частью кода. Часто этот уровень журнала не нужен, так как выброс исключения может передать всю необходимую информацию.

• Сообщение — это объект, описывающий событие. По соглашению, AbstractString сообщения, передаваемые в качестве сообщений, предполагается, что они в формате Markdown. Другие типы будут отображаться с помощью print(io, obj) или string(obj) для текстового вывода и, возможно, show(io,mime,obj) для других мультимедийных дисплеев, используемых в установленных средствах ведения журнала.

• Дополнительные пары «ключ-значение» позволяют прикреплять произвольные данные к каждому событию. Некоторые ключи имеют общепринятое значение, которое может влиять на то, как интерпретируется событие (см. @logmsg).

Система также генерирует стандартную информацию для каждого события:

• Файл, в котором был развернут макрос ведения журнала.
• Строка и столбец, где встречается макрос ведения журнала в исходном коде.
• Уникальный, фиксированный идентификатор для оператора исходного кода, где появляется макрос ведения журнала. Этот идентификатор разработан таким образом, чтобы быть достаточно стабильным, даже если исходный код файла изменяется, при условии, что само оператор ведения журнала остается неизменным.
• Группа для события, которая по умолчанию устанавливается в базовое имя файла без расширения. Это можно использовать для группирования сообщений в более мелкие категории, чем уровень журнала (например, все предупреждения о устаревании имеют группу :depwarn), или в логические группы по или внутри модулей.

Обратите внимание, что некоторые полезные сведения, такие как время события, по умолчанию не включены. Это связано с тем, что такая информация может быть дорогостоящей для извлечения и также динамически доступна текущему средству ведения журнала. Легко определить пользовательское средство ведения журнала для дополнения данных события временем, трассировкой стека вызовов, значениями глобальных переменных и другой полезной информацией по мере необходимости.

Обработка событий журнала

Как видно из примеров, операторы ведения журнала ничего не говорят о том, куда попадают события журнала или как они обрабатываются. Это ключевая особенность проектирования, которая делает систему композиционной и естественной для одновременного использования. Она достигает этого, разделяя две разные задачи:

• Создание событий журнала — это задача автора модуля, который должен решить, где срабатывают события и какую информацию следует включить.
• Обработка событий журнала — то есть отображение, фильтрация, агрегирование и запись — это задача автора приложения, которому необходимо объединить несколько модулей в сотрудничающее приложение.

Средства ведения журнала

Обработка событий выполняется средством ведения журнала, которое является первой настраиваемой частью кода пользователя, которая видит событие. Все средства ведения журнала должны быть подтипами AbstractLogger.

Когда возникает событие, соответствующее средство ведения журнала находится путем поиска локального средства ведения журнала с глобальным средством ведения журнала в качестве резервного варианта. Идея в том, что код приложения знает, как должны обрабатываться события журнала и существует где-то в верхней части стека вызовов. Поэтому мы должны искать вверх по стеку вызовов, чтобы обнаружить средство ведения журнала — то есть средство ведения журнала должно быть динамически областью видимости. (Это момент отличия от фреймворков ведения журнала, где средство ведения журнала имеет лексическую область видимости; явно предоставляется автором модуля или как простая глобальная переменная. В такой системе неудобно управлять ведением журнала при составлении функциональности из нескольких модулей.)

Глобальное средство ведения журнала может быть установлено с помощью global_logger, а локальные для задачи средства ведения журнала — с помощью with_logger. Новые задачи наследуют средство ведения журнала родительской задачи.

Библиотека предоставляет три типа средств ведения журнала. ConsoleLogger — это средство ведения журнала по умолчанию, которое вы видите при запуске REPL. Он отображает события в удобочитаемом текстовом формате и пытается обеспечить простой, но удобный для пользователя контроль над форматированием и фильтрацией. NullLogger — удобный способ отбросить все сообщения там, где это необходимо; это эквивалент потока devnull в ведении журнала. SimpleLogger — это очень простое средство ведения журнала с форматированием текста, в основном полезное для отладки самой системы ведения журнала.

Пользовательские средства ведения журнала должны сопровождаться перегрузками функций, описанных в разделе справочника.

Ранняя фильтрация и обработка сообщений

Когда происходит событие, происходит несколько этапов ранней фильтрации для предотвращения генерации сообщений, которые будут отброшены:

1. Проверяется уровень журнала сообщения на предмет соответствия глобальному минимальному уровню (установленному через disable_logging). Это грубое, но чрезвычайно недорогое глобальное значение.
2. Просматривается текущее состояние средства ведения журнала, и уровень сообщения проверяется на предмет соответствия минимальному уровню средства ведения журнала, как полученному с помощью вызова Logging.min_enabled_level. Это поведение можно переопределить с помощью переменных среды (подробнее об этом позже).
3. Вызывается функция Logging.shouldlog с текущим средством ведения журнала, принимая минимальную информацию (уровень, модуль, группа, идентификатор), которая может быть вычислена статически. Самым полезным образом shouldlog получает событие id, что позволяет отбрасывать события на ранней стадии на основе кэшируемого предиката.

Если все эти проверки пройдены, сообщение и пары «ключ-значение» полностью вычисляются и передаются текущему средству ведения журнала через функцию Logging.handle_message. handle_message() может выполнять дополнительную фильтрацию по мере необходимости и отображать событие на экране, сохранять его в файле и т. д.

Исключения, возникающие при генерации события журнала, по умолчанию перехватываются и регистрируются. Это предотвращает то, что отдельные неисправные события приведут к аварийному завершению приложения, что полезно при включении редко используемых отладочных событий в рабочей системе. Это поведение можно настроить для каждого типа средства ведения журнала путем расширения Logging.catch_exceptions.

Тестирование событий журнала

События журнала являются побочным эффектом выполнения обычного кода, но вы можете захотеть протестировать определённые информационные сообщения и предупреждения. Модуль Test предоставляет макрос @test_logs, который можно использовать для сопоставления с образцом потока событий журнала.

Переменные среды

Фильтрацию сообщений можно контролировать через переменную среды JULIA_DEBUG, которая служит простым способом включения отладочного ведения журнала для файла или модуля. Загрузка julia с JULIA_DEBUG=loading активирует @debug сообщения журнала в loading.jl. Например, в оболочках Linux:

$ JULIA_DEBUG=loading julia -e 'using OhMyREPL'
┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji due to it containing an invalid cache header
└ @ Base loading.jl:1328
[ Info: Recompiling stale cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji for module OhMyREPL
┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/Tokenize.ji due to it containing an invalid cache header
└ @ Base loading.jl:1328
...

В Windows то же самое можно сделать в CMD, выполнив сначала set JULIA_DEBUG="loading" и в Powershell с помощью $env:JULIA_DEBUG="loading".

Аналогично, переменную среды можно использовать для включения отладочного ведения журнала модулей, таких как Pkg, или корней модулей (см. Base.moduleroot). Для включения всего отладочного ведения журнала используйте специальное значение all.

Для включения отладочного ведения журнала из REPL установите ENV["JULIA_DEBUG"] в имя модуля, который вас интересует. Функции, определённые в REPL, относятся к модулю Main; их ведение журнала можно включить следующим образом:

julia> foo() = @debug "foo"
foo (generic function with 1 method)

julia> foo()

julia> ENV["JULIA_DEBUG"] = Main
Main

julia> foo()
┌ Debug: foo
└ @ Main REPL[1]:1

Используйте разделитель запятыми для включения отладки для нескольких модулей: JULIA_DEBUG=loading,Main.

Примеры

Пример: Запись событий журнала в файл

Иногда может быть полезно записывать события журнала в файл. Вот пример того, как использовать локальное для задачи и глобальное средство ведения журнала для записи информации в текстовый файл:

# Load the logging module
julia> using Logging

# Open a textfile for writing
julia> io = open("log.txt", "w+")
IOStream(<file log.txt>)

# Create a simple logger
julia> logger = SimpleLogger(io)
SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())

# Log a task-specific message
julia> with_logger(logger) do
           @info("a context specific log message")
       end

# Write all buffered messages to the file
julia> flush(io)

# Set the global logger to logger
julia> global_logger(logger)
SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())

# This message will now also be written to the file
julia> @info("a global log message")

# Close the file
julia> close(io)

Пример: Включение сообщений уровня отладки

Вот пример создания ConsoleLogger, который пропускает любые сообщения с уровнем журнала, большим или равным Logging.Debug.

julia> using Logging

# Create a ConsoleLogger that prints any log messages with level >= Debug to stderr
julia> debuglogger = ConsoleLogger(stderr, Logging.Debug)

# Enable debuglogger for a task
julia> with_logger(debuglogger) do
           @debug "a context specific log message"
       end

# Set the global logger
julia> global_logger(debuglogger)

Справочник

Модуль ведения журнала

Logging.LoggingМодуль

Создание событий

Logging.@logmsgМакрос

@debug message  [key=value | value ...]
@info  message  [key=value | value ...]
@warn  message  [key=value | value ...]
@error message  [key=value | value ...]

@logmsg level message [key=value | value ...]

@debug "Verbose debugging information.  Invisible by default"
@info  "An informational message"
@warn  "Something was odd.  You should pay attention"
@error "A non fatal error occurred"

x = 10
@info "Some variables attached to the message" x a=42.0

@debug begin
    sA = sum(A)
    "sum(A) = $sA is an expensive operation, evaluated only when `shouldlog` returns true"
end

for i=1:10000
    @info "With the default backend, you will only see (i = $i) ten times"  maxlog=10
    @debug "Algorithm1" i progress=i/10000
end

Logging.LogLevelТип

LogLevel(level)

julia> Logging.LogLevel(0) == Logging.Info
true

Logging.DebugКонстанта

Debug

Logging.InfoКонстанта

Info

Logging.WarnКонстанта

Warn

Logging.ErrorКонстанта

Error

Обработка событий с AbstractLogger

Обработка событий контролируется путем переопределения функций, связанных с AbstractLogger:

Logging.AbstractLoggerТип

Logging.handle_messageФункция

handle_message(logger, level, message, _module, group, id, file, line; key1=val1, ...)

Logging.shouldlogФункция

shouldlog(logger, level, _module, group, id)

Logging.min_enabled_levelФункция

min_enabled_level(logger)

Logging.catch_exceptionsФункция

catch_exceptions(logger)

Logging.disable_loggingФункция

disable_logging(level)

Logging.disable_logging(Logging.Info) # Disable debug and info

Использование логгеров

Установка и проверка логгеров:

Logging.global_loggerФункция

global_logger()

global_logger(logger)

Logging.with_loggerФункция

with_logger(function, logger)

function test(x)
    @info "x = $x"
end

with_logger(logger) do
    test(1)
    test([1,2])
end

Logging.current_loggerФункция

current_logger()

Журналы, предоставляемые системой:

Logging.NullLoggerТип

NullLogger()

Logging.ConsoleLoggerТип

ConsoleLogger([stream,] min_level=Info; meta_formatter=default_metafmt,
              show_limited=true, right_justify=0)

Logging.SimpleLoggerТип

SimpleLogger([stream,] min_level=Info)