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

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

Используйте разделитель запятых для включения отладки для нескольких модулей: 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Модуль

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

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)