08.03.2023 17:52
yaznahar 19 2200 Источник
Log в переводе с английского «бревно»
Log в переводе с английского «бревно»

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

Первое, что приходит на ум, – запомнить позицию в файле, на которой мы закончили. Её возвращает функция tell. На следующей итерации перейдём сразу на эту позицию и продолжим чтение оттуда. Это делает функция seek практически бесплатно.

Схема простая и рабочая, но при ротации лога возникают проблемы. Во-первых, переход за границу файла не приведёт к ошибке, просто при чтении мы получим пустые данные. Значит, перед переходом надо проверить, что сохранённое значение не превышает размер файла, и если это не так, читать лог с начала. Даже в таком случае после ротации может записатся достаточно данных для успешного прохождения проверки. Тогда мы как ни в чём не бывало продолжим «с места, где закончили» и пропустим кусок данных.

Есть способ усовершенствовать алгоритм: запоминать смещение не конца файла, а начала последней прочитанной строки и её значение. В этом случае мы также перейдём на закешированную позицию, а потом прочитаем строку и сравним её с сохранённой. Если значения совпали, продолжаем чтение дальше. Если различаются, возвращаемся к началу файла. Так как в каждой строке лога обычно есть метка времени, успешное прохождение проверки после ротации практически невозможно.

Я реализовал эту идею в небольшом Python модуле. Он называется cutthelog. В нём есть единственный класс CutTheLog, позволяющий открыть файл и выполнить описанную проверку. Как результат он возвращает итератор по непросмотренным строкам лога. Для создания объекта передаём путь файла и опционально смещение и значение строки, на которой мы закончили чтение. Выглядит это так:

import sys
from cutthelog import CutTheLog

ctl = CutTheLog('/var/log/syslog', offset=7777, last_line=b'...')
with ctl as line_iter:
  print('Starting at:', ctl.get_position(), end='', file=sys.stderr)
  for line in line_iter:
		print(line.decode(), end='')
print('Ending at:', ctl.get_position(), end='', file=sys.stderr)

Строки лога имеют тип bytes, так как даже на моей дескпотной убунте в логе /var/log/syslog есть символы, которые нельзя декодировать в юникод. Каждая строка возвращённая итератором, обновляет позицию внутри объекта. Значит, мы можем читать произвольное количество строк, а не только до конца файла. В классе есть методы для сохранения позиции в кеш на диске и чтения её оттуда.

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

$ echo -e "one\ntwo\nthree" > example
$ cutthelog example
one
two
three
$ cutthelog example
$ echo -e "four\nfive\nsix" >> example
$ cutthelog example
four
five
six
$ cutthelog example
$ echo -e "seven\neight\nnine\nten\neleven\ntwelve" > example
$ cutthelog example
seven
eight
nine
ten
eleven
twelve

Кеш хранится в файле .cutthelog в домашней директории пользователя. Запуск под другим пользователем выведет файл полностью. Путь до кеша можно задать вручную опцией -c/--cache-file.

Код модуля находится на github. Python пакет доступен на pypi. Надеюсь, они будут вам полезны.

Комментарии (19)


  1. miga
    00.00.0000 00:00
    #25304958

    У меня есть одна утилитка с альтернативным подходом - тейлить логи за последние N секунд. Логи-то отсортированы, содержат таймстамп так что бинарный поиск нужного места - весьма дешев.


    1. yaznahar Автор
      00.00.0000 00:00
      #25305300

      Подход действильно альтернитивный, но непонятно, чем он лучше) Зато понятно, чем хуже. Форматы таймспампа в логах разных приложений могут сильно отличаться: там может отсутствовать года, там могут присутствовать нелатинские буквы. Написать универсальный парсер для всего этого, та ещё задачка...


      1. miga
        00.00.0000 00:00
        #25305682

        Форматы таймстампа действительно могут быть разные и утилитка это умеет. А парсер для форматов называется strptime(3) и он уже давно написан :)

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


  1. dyadyaSerezha
    00.00.0000 00:00
    #25305130

    По-моему проблема высосана из пальца, хотя, может, и в случае автора она актуальна. Но в большинстве случаев каждая запись в логе имееи таймстэмп и в логах всегда ищется место по времени инцидента и дальше смотрится, что было непосредственно перед этим. Зачем мне смотреть с последнего просмотренного места? Там гигабайты и гигабайты новых логов!


    1. yaznahar Автор
      00.00.0000 00:00
      #25305286

      Например, чтобы узнавать о проблеме до того, как её заметять пользователи и случится инцидент. Фоновый мониторинг логов на типовые записи о проблемах – стандартная практика.


      1. dyadyaSerezha
        00.00.0000 00:00
        #25305488

        Согласен, но там этим занят специальный сервис (из коробки или свой), и если он падает, то при перезауске просто продолжает мониторить с конца лога (если свой). Перезапустить сервис - секунды. Делается это тоже автоматически.

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


    1. svk28
      00.00.0000 00:00
      #25305816

      Логи бывают разные. К примеру журнал 1С.


  1. dph
    00.00.0000 00:00
    #25305132
    +2

    А зачем вообще руками смотреть логи, да еще и запоминать позицию? Вроде бы уже XXI век, для постоянной работы с логами есть куча утилит и стоит пользоваться именно ими.


    1. yaznahar Автор
      00.00.0000 00:00
      #25305242
      -1

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

      $ cutthelog logfile > /dev/null

      а потом добавляем в cron вызов такого однострочника с нужным интервалом

      [ $(cutthelog logfile | grep "some error" | wc -l) -ge ${THRESHOLD} ] && echo "ALARM"

      Теперь расскажите, как можно решить эту задачу с помощью вашей кучи утилит.


      1. dph
        00.00.0000 00:00
        #25305280
        +5

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

        Ну вот серьезно, уже XXI век на дворе, откуда эти идеи времен "приходящих виндовс-админов"?


        1. Lazhu
          00.00.0000 00:00
          #25306228

          Виндовые одмины они такие. Им невдомек, что tail существует уже лет 50


        1. yaznahar Автор
          00.00.0000 00:00
          #25306368

          Чтобы навесить алерт в графане туда должна прилетать метрика с хоста. Чтобы метрика прилетала, на хосте должен работать собирающий её агент. Чтобы посчитать метрику за прошедший интервал, агент должен открыть лог файл, найти место, где закончил читать его в про... oh, wait!.. так вот же код агента:

          echo "stats.${HOSTNAME}.metric_name $(cutthelog logfile | grep "some error" | wc -l) $(date +%s)" | nc ${GRAPHITE} ${GRAPHITE_PORT}

          Даже в XXII веке утилита и cron будут актуальны. Все логи будут отправлять в ChatGPT бот, чтобы он разобрался, что делать:

          cutthelog logfile | send_to_chatgpt_bot


          1. dph
            00.00.0000 00:00
            #25306440

            Нет, зачем там метрика с хоста? Достаточно метрики на основании запроса в систему логов, так все и делают обычно.


  1. anatolykern
    00.00.0000 00:00
    #25305906

    splunk, graylog, elk, newrelic и прочие уже не в моде?


  1. dph
    00.00.0000 00:00
    #25307130

    Кстати, yaznahar, а вы действительно не знаете про современные подходы к observability?
    Про системы сбора и хранения метрик, про системы сбора и хранения логов, про разделение метрик, логов и трейсов, про алертинги, про концепцию сайдкаров, про изоляцию продакшена от админов и разработчиков, про контейнеризацию и так далее и так далее?
    Пост действительно выглядит как пришедший из прошлого тысячелетия.


    1. yaznahar Автор
      00.00.0000 00:00
      #25307266

      Действительно слышал про все эти системы сбора и хранения метрик только краем уха, потому что на масштабах, с которыми работаю, они превращаются в тыкву, и нужно придумывать что-то своё.


      1. dph
        00.00.0000 00:00
        #25307344

        Хм, они нормально работают от масштабов "один маленький сервер в чужом облаке" и до масштабов Гугла. А у тебя какой масштаб?


        1. yaznahar Автор
          00.00.0000 00:00
          #25307376

          Больше десяти тысяч серверов. Завидую твоей осведомлённости о том, как всё работает у Гугла.


          1. dph
            00.00.0000 00:00
            #25307856

            На 10000 серверах на каждом есть пайтон для запуска скриптов, написанных разработчиком? И к каждому с доступом на выполнение скриптов? И с логами, которые пишутся в файлы?
            Я не верю )