Как сделать лог программы
Логирование или как вести летопись работы программы
Написали программу с применением нейросети, но она выдает кучу ошибок? Где потом искать эти ошибки? Как структурировать полученную информацию?
Помочь с поиском ошибок может логирование — группа методов для сбора и сохранения информации о работе программы. Всю интересующую нас информацию мы можем записывать в текстовые файлы и потом их обрабатывать. К примеру, вот таким образом в случае деления на 0:
Тогда консоль нам покажет следующее:
А в логе с файлом увидим:
Конечно, реализовать самостоятельно такой способ — просто, и многие этим пользуются. Но у него тоже есть минус: если проект большой, надо не забывать придерживаться определенного формата их заполнения.
Но Python же один из самых дружелюбных языков.) Разработчики уже подумали о нас и создали хорошую библиотеку «logging».
Для работы с ней нам необходимо импортировать библиотеку logging и указать основные параметры. Всего параметров для настройки 6.
Так же существует 5 уровней логирования информации: от DEBUG (отладка) до critical (критичные ошибки).
На этом можно закончить с теорией, и перейдем к практике.
Теперь мы будем логировать нашу функцию деления уже с учетом модуля logging и попытаемся собрать максимум информации о ее работе. Давайте рассмотрим код нашего простенького скрипта, но уже с учетом использования логов.
Как мы видим он немного увеличился в размерах, но при этом, для записи также использует лишь одна строчка.
После – мы указываем уровень лога и имя файла, в который мы будем его записывать:
В конце нам надо создать формат записи, в котором мы укажем: время записи, имя скрипта, названия уровня и само сообщение. Остается только применить данный формат для нашего «логгера».
Вот, на этом и все) В дальнейшем мы можем использовать наш логгер простым вызовом logger.info(‘Division’) или в случае описания ошибки logger.error(error_text). По окончанию работы скрипта данные будут сохранены в файл ‘data.log’.
А теперь посмотрим, что мы получили в логе:
Запись со временем, уровнем и сообщением! Такой лог, во-первых – удобно читать, а, во-вторых – удобно обрабатывать!
Использование модуля «logger» на маленьких программах, может, и не заметно, а вот на больших польза становится очевидна. Особенно, если эти логи в дальнейшем нуждаются в обработке, например, для Process Mining-а.
Вот таким простым способом мы с вами научились делать понятную и удобную запись логов в нашем скрипте!
Вертим логи как хотим ― анализ журналов в системах Windows
Пора поговорить про удобную работу с логами, тем более что в Windows есть масса неочевидных инструментов для этого. Например, Log Parser, который порой просто незаменим.
В статье не будет про серьезные вещи вроде Splunk и ELK (Elasticsearch + Logstash + Kibana). Сфокусируемся на простом и бесплатном.
Журналы и командная строка
До появления PowerShell можно было использовать такие утилиты cmd как find и findstr. Они вполне подходят для простой автоматизации. Например, когда мне понадобилось отлавливать ошибки в обмене 1С 7.7 я использовал в скриптах обмена простую команду:
Она позволяла получить в файле fail.txt все ошибки обмена. Но если было нужно что-то большее, вроде получения информации о предшествующей ошибке, то приходилось создавать монструозные скрипты с циклами for или использовать сторонние утилиты. По счастью, с появлением PowerShell эти проблемы ушли в прошлое.
Основным инструментом для работы с текстовыми журналами является командлет Get-Content, предназначенный для отображения содержимого текстового файла. Например, для вывода журнала сервиса WSUS в консоль можно использовать команду:
Для вывода последних строк журнала существует параметр Tail, который в паре с параметром Wait позволит смотреть за журналом в режиме онлайн. Посмотрим, как идет обновление системы командой:
Смотрим за ходом обновления Windows.
Если же нам нужно отловить в журналах определенные события, то поможет командлет Select-String, который позволяет отобразить только строки, подходящие под маску поиска. Посмотрим на последние блокировки Windows Firewall:
Смотрим, кто пытается пролезть на наш дедик.
При необходимости посмотреть в журнале строки перед и после нужной, можно использовать параметр Context. Например, для вывода трех строк после и трех строк перед ошибкой можно использовать команду:
Оба полезных командлета можно объединить. Например, для вывода строк с 45 по 75 из netlogon.log поможет команда:
Для получения списка доступных системных журналов можно выполнить следующую команду:
Вывод доступных журналов и информации о них.
Для просмотра какого-то конкретного журнала нужно лишь добавить его имя. Для примера получим последние 20 записей из журнала System командой:
Последние записи в журнале System.
Для получения определенных событий удобнее всего использовать хэш-таблицы. Подробнее о работе с хэш-таблицами в PowerShell можно прочитать в материале Technet about_Hash_Tables.
Для примера получим все события из журнала System с кодом события 1 и 6013.
В случае если надо получить события определенного типа ― предупреждения или ошибки, ― нужно использовать фильтр по важности (Level). Возможны следующие значения:
Собрать хэш-таблицу с несколькими значениями важности одной командой так просто не получится. Если мы хотим получить ошибки и предупреждения из системного журнала, можно воспользоваться дополнительной фильтрацией при помощи Where-Object:
Ошибки и предупреждения журнала System.
Аналогичным образом можно собирать таблицу, фильтруя непосредственно по тексту события и по времени.
Подробнее почитать про работу обоих командлетов для работы с системными журналами можно в документации PowerShell:
PowerShell ― механизм удобный и гибкий, но требует знания синтаксиса и для сложных условий и обработки большого количества файлов потребует написания полноценных скриптов. Но есть вариант обойтись всего-лишь SQL-запросами при помощи замечательного Log Parser.
Работаем с журналами посредством запросов SQL
Утилита Log Parser появилась на свет в начале «нулевых» и с тех пор успела обзавестись официальной графической оболочкой. Тем не менее актуальности своей она не потеряла и до сих пор остается для меня одним из самых любимых инструментов для анализа логов. Загрузить утилиту можно в Центре Загрузок Microsoft, графический интерфейс к ней ― в галерее Technet. О графическом интерфейсе чуть позже, начнем с самой утилиты.
О возможностях Log Parser уже рассказывалось в материале «LogParser — привычный взгляд на непривычные вещи», поэтому я начну с конкретных примеров.
Для начала разберемся с текстовыми файлами ― например, получим список подключений по RDP, заблокированных нашим фаерволом. Для получения такой информации вполне подойдет следующий SQL-запрос:
Посмотрим на результат:
Смотрим журнал Windows Firewall.
Разумеется, с полученной таблицей можно делать все что угодно ― сортировать, группировать. Насколько хватит фантазии и знания SQL.
Log Parser также прекрасно работает с множеством других источников. Например, посмотрим откуда пользователи подключались к нашему серверу по RDP.
Работать будем с журналом TerminalServices-LocalSessionManager\Operational.
Не со всеми журналами Log Parser работает просто так ― к некоторым он не может получить доступ. В нашем случае просто скопируем журнал из %SystemRoot%\System32\Winevt\Logs\Microsoft-Windows-TerminalServices-LocalSessionManager%4Operational.evtx в %temp%\test.evtx.
Данные будем получать таким запросом:
Смотрим, кто и когда подключался к нашему серверу терминалов.
Особенно удобно использовать Log Parser для работы с большим количеством файлов журналов ― например, в IIS или Exchange. Благодаря возможностям SQL можно получать самую разную аналитическую информацию, вплоть до статистики версий IOS и Android, которые подключаются к вашему серверу.
В качестве примера посмотрим статистику количества писем по дням таким запросом:
Если в системе установлены Office Web Components, загрузить которые можно в Центре загрузки Microsoft, то на выходе можно получить красивую диаграмму.
Выполняем запрос и открываем получившуюся картинку…
Любуемся результатом.
Следует отметить, что после установки Log Parser в системе регистрируется COM-компонент MSUtil.LogQuery. Он позволяет делать запросы к движку утилиты не только через вызов LogParser.exe, но и при помощи любого другого привычного языка. В качестве примера приведу простой скрипт PowerShell, который выведет 20 наиболее объемных файлов на диске С.
Ознакомиться с документацией о работе компонента можно в материале Log Parser COM API Overview на портале SystemManager.ru.
Благодаря этой возможности для облегчения работы существует несколько утилит, представляющих из себя графическую оболочку для Log Parser. Платные рассматривать не буду, а вот бесплатную Log Parser Studio покажу.
Интерфейс Log Parser Studio.
Основной особенностью здесь является библиотека, которая позволяет держать все запросы в одном месте, без россыпи по папкам. Также сходу представлено множество готовых примеров, которые помогут разобраться с запросами.
Вторая особенность ― возможность экспорта запроса в скрипт PowerShell.
В качестве примера посмотрим, как будет работать выборка ящиков, отправляющих больше всего писем:
Выборка наиболее активных ящиков.
При этом можно выбрать куда больше типов журналов. Например, в «чистом» Log Parser существуют ограничения по типам входных данных, и отдельного типа для Exchange нет ― нужно самостоятельно вводить описания полей и пропуск заголовков. В Log Parser Studio нужные форматы уже готовы к использованию.
Помимо Log Parser, с логами можно работать и при помощи возможностей MS Excel, которые упоминались в материале «Excel вместо PowerShell». Но максимального удобства можно достичь, подготавливая первичный материал при помощи Log Parser с последующей обработкой его через Power Query в Excel.
Приходилось ли вам использовать какие-либо инструменты для перелопачивания логов? Поделитесь в комментариях.
Новый подход к просмотру логов
Одно время, приходилось много работать с логами. Они могли быть большими и находиться на разных серверах. Требовалось не найти что-то конкретное, а понять почему система ведёт себя не так как надо. По некоторым причинам, лог-агрегатора не было.
Хотелось иметь просмотрщик логов, позволяющий, в любой момент, открыть любой файл, без скачивания на локальную машину, как команда less в linux консоли. Но при этом, должна быть удобная подсветка текста, как в IDE, и фильтрация записей по различным параметрам. Фильтрация и поиск должны работать по событиям в логе, а не по строкам, как grep, это важно когда есть многострочные записи, например ошибки со стектрейсами. Так же должна быть возможность просматривать записи сразу из нескольких файлов на одной странице, смёржив их по таймстемпу, даже если файлы находятся на разных нодах.
И я придумал как сделать такую утилиту!
Предвижу вопросы о производительности типа «Разве можно быстро фильтровать записи без индексации? В плохих случаях придётся остcканировать весь лог чтобы найти хоть одну запись подходящую под фильтр». Во первых, сканирование лога работает довольно быстро, 1Гб читается около 3,5сек, это терпимо. Во вторых, обычно известен временной интервал, в котором ищем проблему, если задан фильтр по дате, то будет сканироваться только та часть файла, в которой находятся записи относящиеся к тому времени. Найти границу временного интервала в файле можно очень быстро бинарным поиском.
Отображение лога
Чтобы легче различать границы одной записи, запись под курсором подсвечивается прямоугольником; поле severity подсвечивается различными цветами в зависимости от значения, парные скобки подсвечиваются когда наводишь курсор на одну из них.
Имя логгера тоже сокращено: «
.SecurityManager». Показывается только имя класса, а пакет сворачивается в «
Фолдинг влияет только на отображение, поиск работает по оригинальному тексту. Если совпадение найдётся в сокращённой части текста, то эта часть текста автоматически появится. Также, если пользователь выделит текст и нажмёт Ctrl+C, в буфер скопируется исходный текст, без всяких сокращений.
Архитектура позволяет легко навешивать на текст подсветку или всплывающие подсказки, благодаря этому, сделаны разные приятные мелочи типа показа даты в человеческом формате, если она напечатана в виде числа:
Фильтрация
Набор фильтров зависит от формата лога. Некоторые фильтры доступны всегда, например фильтр по подстроке, а некоторые появляются если в логе присутствует поле определённого типа. Это позволяет создавать специализированные фильтры для некоторых типов полей. Например, если в логе есть поле severity, то в верхней панельке появится такой UI компонент:
Очень удобно добавлять фильтры из контекстного меню. Можно выделить текст, кликнуть правой кнопкой мыши и выбрать «Не показывать записи с таким текстом». На панельку с фильтрами автоматически добавится фильтр по тексту, скрывающий записи с таким текстом. Помогает когда лог завален однообразными записями, не интересными в данный момент.
Добавление фильтров из контекстного меню
Можно кликнуть на запись и выбрать «Скрыть последующие записи» или «Скрыть предыдущие записи», чтобы работать только с определённой частью лога. Скрытие происходит добавлением фильтра по дате.
Для сложных случаев можно задать фильтр с условием написанным на JavaScript. Такой фильтр представляет из себя функцию принимающую одну записи и возвращающую true или false.
Пример фильтра на JavaScript
При изменении фильтров, просмотрщик старается максимально сохранить позицию в логе. Если есть выделенная запись, то изменение фильтров не изменит её положения на экране, а записи вокруг пропадут или появятся. Пользователь может задать фильтр, чтобы были видны только ошибки, найти подозрительную ошибку, затем убрать фильтр и смотреть что происходило вокруг этой ошибки.
Состояние панели фильтров отображается в параметрах URL, чтобы можно было добавить в закладки браузера текущую конфигурацию.
Мелкие, но полезные фичи
Когда находишь что-то интересное — хочется поделиться этим с командой, для этого можно создать специальную ссылку на текущую позицию в логе, и любой кто её откроет увидит точно такую же страницу, которая была при создании ссылки, включая состояние фильтров, текста в поле поиска, выделенной записи и т.д.
Если сервер расположен в другой таймзоне, над текстом с датой будет всплывающая подсказка с датой в таймзоне пользователя.
Конфигурация
Я старался сделать конфигурацию как можно проще, чтобы всё работало из коробки. Если попросить пользователя задать формат лога, то большинство просто закроют приложение и пойдут смотреть по старинке. Поэтому формат лога распознаётся автоматически. Конечно, это работает не всегда и часто не точно. Для таких случаев можно задать формат лога вручную в файле конфигурации. Можно использовать паттерны log4j, logback или просто регексп. Если ваш лог не распознался, но вам кажется что должен — создайте issue на GitHub, этим вы поможете проекту.
Самая нужная настройка — список видимых файлов. По умолчанию доступны все файлы с расширением «.log» и видна вся структура каталогов, но это не очень хорошо с точки зрения секьюрити. В конфигурационном файле можно ограничить видимость файлов с помощью списка паттернов типа такого:
/work и её поддиректориях.
Более подробная информация в документации на GitHub.
Работа с несколькими нодами
Мёрж файлов, расположенных на разных нодах — это киллер фича, ради которой и затевался проект. Как я уже говорил, файл никогда не скачивается полностью с одной ноды на другую и не индексируется. Поэтому, на каждой из нод должен быть запущен Log Viewer. Пользователь открывает web UI на одной из нод, указывает расположение логов, и Log Viewer коннектится к другим инстансам LogViewer чтобы подгружать содержимое лога через них. Записи из всех открытых файлов мёржатся по таймстемпу и показываются как буд-то это один файл.
Вкратце опишу как это работает под капотом. Когда пользователь открывает страницу, надо показать конец лога, для этого на каждую ноду отправляется запрос «дай последние N записей», где N — количество строк помещающихся на экран. Полученные записи сортируются по таймстемпу, берутся последние N записей и показываются пользователю. Когда пользователь скролит страницу вверх, на все ноды посылается запрос «дай последние N записей с таймстемпом меньше T», где T — таймстемп самой верхней записи на экране. Полученные записи сортируются и добавляются на страницу. При скроле вниз происходит тоже самое, только в другую сторону. Поиск позиции в файле, где находятся записи старше/младше T, работает очень быстро, так как записи отсортированы по таймстемпу и можно использовать бинарный поиск. Там есть много нюансов, но общая схема такая. Мёрж работает только если система смогла определить фомат лога и в каждой записи задан полный тайстемп.
На данный момент, нет UI для выбора файлов на разных нодах, приходится прописывать файлы в параметрах URL в таком виде:
http://localhost:8111/log?path=/opt/my-app/logs/a.log@hostname1&path=/opt/my-app/logs/b.log@hostname1&path=/opt/my-app/logs/c.log@hostname2
здесь каждый параметр «path» задаёт один файл, после «@» указывается хост, на котором лежит файл и запущен инстанс просмотрщика логов. Можно указать несколько хостов через запятую. Если «@» отсутствует — файл находится на текущей ноде. Чтобы не иметь дела с огромными URL, есть возможность задать короткие ссылки в конфигурации, в разделе log-paths = < … >.
Встраивание просмотрщика в своё приложение
Log Viewer можно подключить к своему Java Web приложению как библиотеку, чтобы оно могло показывать пользователю свои логи. Иногда это удобней чем запуск отдельным приложением. Достаточно просто добавить зависимость на библиотеку библиотеку через Maven/Gradle и подключить один конфигурационный класс в spring context. Всё остальное сконфигурится автоматически, log viewer сам распознает какая система логгирования используется и возьмёт из её конфигурации расположение и формат логов. По умолчанию UI маппится на /logs, но всё можно кастомизировать. Пока автоматическая конфигурация работает только с Log4j и Logback.
Это тестировалось на маленьком количестве приложений, если у вас возникнут проблемы — смело пишите в discussions на GitHub.
Что планируется сделать в будущем
Было бы удобно, если бы была возможность оставлять комментарии к записям. Например, прикрепить номер тикета к сообщению об ошибке. Комментарий должен быть виден всем пользователям и, когда такая же ошибка вылетит в следующий раз, будет понятно что с ней делать.
Есть много идей по мелкому улучшению UI. Например, если в тексте встретился кусок JSON, то хочется чтобы просмотрщик умел показывать его в отформатированном виде, а не одной строкой. Хочется иметь возможность задать фильтр по severity для отдельного класса, а не сразу для всех.
Иногда нет возможности открыть порт на сервере для просмотра логов, есть только SSH доступ. Можно сделать поддержку работы через SSH. Web UI будет подниматься на локальной машине, коннектиться через SSH к серверу и запускать там специального агента. Агент будет принимать команды через input stream и возвращать нужные части лога через output stream.