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

Модуль 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).

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

• Место, в котором макрос ведения журнала был расширен.
• Строка и столбец, где появляется макрос ведения журнала в исходном коде.
• Сообщение id — это уникальный, фиксированный идентификатор выражения исходного кода, в котором появляется макрос ведения журнала. Этот идентификатор предназначен для сохранения стабильности, даже если исходный код файла изменится, до тех пор, пока само утверждение ведения журнала останется неизменным.
• Группа group для события, которая по умолчанию установлена в имя файла без расширения. Это можно использовать для группировки сообщений более тонко, чем уровень журнала (например, все предупреждения об устаревании имеют группу :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:

$ 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
...

Аналогично, переменную окружения можно использовать для включения отладочного ведения журнала для модулей, таких как 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

Примеры

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

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

# 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Модуль

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

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)