Как правильно распарсить access лог Nginx/Apache

Наверняка у многих возникает такая задача – извлечь какие-то данные из Access лога Apache или Nginx. Записи лога обычно выглядят как то так:

91.77.238.152 - - [02/Dec/2013:20:31:45 +0400] "GET /blog/2012/01/31/plagin-l2tp-dlya-networkmanager/ HTTP/1.1" 200 70666 "http://yandex.ru/clck/jsredir?text=%D0%BF%D0%BB%D0%B0%D0%B3%D0%B8%D0%BD%20l2tp%20%D0%B4%D0%BB%D1%8F%20networkmanager&uuid=..." "Mozilla/5.0 (X11; U; Linux i686; ru; rv:1.9.1.16) Gecko/20111108 Iceweasel/3.5.16 (like Firefox/3.5.16)"

На первый взгляд кажется, что форматирование этой строки какое-то нелогичное и ничем не оправданное: где то значения заключены в кавычки, где-то в квадратные скобки, где то значение записано как есть. Из за этого кто-то пытается сконструировать огромную нечитаемую регулярку, которую приходится каждый раз писать заново, из за того, что через неделю понять что же она делает нереально. Кто то разбивает строку по пробелам и надеется на лучшее, при этом поле даты разрезается на 2 части а User-Agent превращается вообще в необрабатываемое месиво.

Мы же поступим иначе – попробуем найти систему в структуре этой строки и напишем полноценный лексический анализатор.

Пусть термин “лексический анализатор” вас не пугает – далее увидим, что ничего сложного в этом нет.

Ищем структуру

Попробуем разобраться какие различные способы записи полей встречаются в строке лога.

  • Запись значения как есть: 91.77.238.152 – IP адрес, 200 – код ответа, 70666 – размер ответа. Видим, что таким образом записываются цифровые поля и IP адрес – в которых не может содержаться пробелов в принципе.
  • Запись в квадратных скобках:  [02/Dec/2013:20:31:45 +0400] – дата и время запроса. Очевидно, что в квадратных скобках у нас даты.
  • Запись в двойных кавычках: "GET /blog...ager/ HTTP/1.1" – строка запроса,  "http://yandex.ru/clck..." – реферер, "Mozilla/5.0 (X11; U; Linux ... Firefox/3.5.16)" – User-Agent. Фактически это данные, приходящие от пользователей, которые могут содержать в том числе и пробелы.
  • Можно выделять в отдельный тип, а можно и нет дефис в кавычках или без них: -, "-". Так обозначается отсутствующее значение.
  • Ну и собственно пробел – разделитель полей.

Ну что-же, со структурой вроде стало понятнее. Оказывается всё довольно логично – где есть пробел – заключаем в кавычки, где нет – пишем как есть, даты в квадратные скобки.

Лексический анализатор

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

  • '\s+' – выражение, которое соответствует одному и более пробелам для разделителей полей
  • '"([^"]+)"' – выражение, которое соответствует заключенному в двойные кавычки значению. Круглыми скобками выделим содержимое, находящееся между кавычками для облегчения дальнейшей обработки. Случай с экранированием кавычек "Mozilla \"compatible\" MSIE" пока опустим
  • '\[([^\]]+)\]' – выражение, соответствующее выражению, заключённому в парные квадратные скобки. Так же содержимое выделено круглыми скобками.
  • '([^\s]+)' – выражение, записанное как есть. Обратите внимание – мы пользуемся тем фактом, что записанное как есть выражение не может содержать пробелов.
  • '-|"-"' – отсутствующее значение. Может быть заключено в кавычки, а может и нет.

Было бы полезно выражение, записанное “как есть” разбить на 2 типа – число и строка. Тогда регулярные выражения выглядели бы как '([0-9]+)' и '([^\s]+)' соответственно. Но мы этот момент пропустим.

Дальше будет код на Python, но он простой. Должно быть понятно, даже если не знаете языка. Попробуем декларативно задать правила для нашего анализатора

# lexeme types
WSP, QUOTED_STRING, DATE, RAW, NO_DATA = range(5) # ENUM

RULES = [
    ('\s+', WSP),
    ('-|"-"', NO_DATA),
    ('"([^"]+)"', QUOTED_STRING),
    ('\[([^\]]+)\]', DATE),
    ('([^\s]+)', RAW),
    ]

Можно заметить, что регулярные выражения для QUOTED_STRING, для RAW и для NO_DATA конфликтуют между собой. Действительно, строка "-", которая, по идее является NO_DATA прекрасно попадает под шаблон QUOTED_STRING (т.к. заключено в кавычки) и даже под RAW (т.к. не содержит пробелов). Эту проблему мы обойдём, применяя правила последовательно одно за другим до тех пор, пока одно из них не сработает. Т.к. правило для NO_DATA находится выше, то на значении "-" до конфликтующих QUOTED_STRING и RAW дело просто не дойдёт:

import re

def Lexer(rules):
    # предварительно компилируем регулярные выражения для ускорения работы
    prepared = [(re.compile(regexp), token_type) for regexp, token_type in rules]

    def lex(line):
        ll = len(line) # длина строки лога - чтобы знать, когда остановиться
        i = 0          # текущая позиция анализатора
        while i < ll:
            for pattern, token_type in prepared:  # пробуем регулярные выражения по очереди
                match = pattern.match(line, i)    # проверяем соответствует ли регулярное выражение строке с позиции i
                if match is None:                 # если нет - пробуем следующую регулярку
                    continue
                i = match.end()                   # передвигаем позицию анализатора до индекса, соответствующего концу совпадения
                yield (match, token_type)         # возвращаем найденный токен
                break                             # начинаем анализировать остаток строки с новым значением сдвига i
            # по хорошему, в этом месте нужно кидать ошибку SyntaxError(line, i) в случае, если ни один из шаблонов не совпал
    return lex

lexer = Lexer(RULES)

То есть смотрите – пробуем по очереди применить регулярку, пока не найдётся совпадающая. После этого захватываем столько, сколько можем захватить этой регуляркой и возвращаем захваченное как очередной токен. А с незахваченным остатком строки повторяем операцию сначала (рекурсивно).

Например, для приведённой в начале поста строки лога вывод будет следующим:

Сама строка:

91.77.238.152 - - [02/Dec/2013:20:31:45 +0400] "GET /blog/2012/01/31/plagin-l2tp-dlya-networkmanager/ HTTP/1.1" 200 70666 "http://yandex.ru/clck/jsredir?text=%D0%BF%D0%BB%D0%B0%D0%B3%D0%B8%D0%BD%20l2tp%20%D0%B4%D0%BB%D1%8F%20networkmanager&uuid=..." "Mozilla/5.0 (X11; U; Linux i686; ru; rv:1.9.1.16) Gecko/20111108 Iceweasel/3.5.16 (like Firefox/3.5.16)"

Вывод лексера:

[('91.77.238.152', RAW),
(' ', WSP),
('-', NO_DATA),
(' ', WSP),
('-', NO_DATA),
(' ', WSP),
('02/Dec/2013:20:31:45 +0400', DATE),
(' ', WSP),
('GET /blog/2012/01/31/plagin-l2tp-dlya-networkmanager/ HTTP/1.1', QUOTED_STRING),
(' ', WSP),
('200', RAW),
(' ', WSP),
('70666', RAW),
(' ', WSP),
('http://yandex.ru/clck/js...', QUOTED_STRING),
(' ', WSP),
('Mozilla/5.0 (X11; U; Lin...', QUOTED_STRING)]

По факту вывод в Python немного отличается, т.к. возвращаются объекты re.MatchObject, но идея понятна.
Фактически уже в таком виде можно начать пользоваться результатом. Например, посчитать с какого IP поступило больше всего запросов или построить гистограмму по количеству запросов в минуту. Но мы пойдём дальше, и напишем простейший синтаксический анализатор.

Парсер

Писать полноценный парсер для такой простейшей плоской структуры смысла нет, поэтому мы просто обработаем каждый тип токена (превратим NO_DATA в Python None, DATE в Python datetime объект и т.п.) и создадим для каждой строки лога Python объект с именованными полями.

import sys
import datetime
import logging

class LogEntry(object):
    FIELDS = ('remote_addr', '_skip', 'remote_user', 'time_local', 'request', 'status',
              'body_bytes_sent', 'http_referer', 'http_user_agent')
    __slots__ = FIELDS  # экономим память

lexer = Lexer(RULES)

for line in sys.stdin:  # читаем построчно из stdin
    try:
        tokens = lexer(line)
    except Exception:
        logging.exception("Error in line '%s'", line)
        continue  # пропускаем битые строки
    entry = LogEntry()
    field_idx = 0
    for re_match, token_type in tokens:
        # к сожалению, в Python нет конструкции switch/case
        if token_type == WSP:
            continue  # пробелы игнорируем
        elif token_type ==  NO_DATA:
            value = None  # NO_DATA заменяем на None
        elif token_type == RAW:
            value = re_match.group(1)  # MatchObject.group(i) возвращает i-ую заключённую в круглые скобки группу
        elif token_type == QUOTED_STRING:
            value = unescape_double_quotes(re_match.group(1))  # снимаем экранирование с заэкранированных кавычек
        elif token_type == DATE:
            value = datetime.datetime.strptime(re_match.group(1), "%d/%b/%Y:%H:%M:%S")  # парсим дату
        else:
            raise SyntaxError("Unknown token", token_type, re_match)

        field_name = LogEntry.FIELDS[field_idx]
        setattr(entry, field_name, value)
        field_idx += 1
    print entry.remote_addr, entry.time_local, entry.request.split()[1]

Выводы

Конечно, по сравнению с одной развесистой регуляркой у нас получилось намного больше кода, да и работать будет наверняка помедленнее. Но, при всех недостатках, наш вариант гораздо легче читается. Опять – же, легче вносить изменения. Если администратор вдруг захочет добавить в лог дополнительные поля (ID сессии пользователя, значение X-Forwarded-For, время ответа), нам достаточно будет изменить лишь атрибут FIELDS класса LogEntry.

Возможно повторное использование кода – например вся функция Lexer универсальная – ей можно скормить любые лексические правила и она будет их использовать (попробуйте написать правила для лексера JSON).

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

Домашнее задание

  • Реализовать распознавание escaped quotes, например "Mozilla \"compatible\" MSIE" и, соответственно, функцию unescape_double_quotes(quoted_string).
  • Реализовать распознавание чисел (int и float) в лексере. Можно добавить отдельное правило для IP адреса.

6 thoughts on “Как правильно распарсить access лог Nginx/Apache

  1. WST

    Годно. Кстати, тот же nginx позволяет легко настроить формат записей в логе.

    Reply
    1. P.S. Post author

      Да, через log_format настраивается.
      Приходится надеяться на сознательность админов, что они не начнуть ломать как то синтаксис, записывая данные, содержащие пробелы, без кавычек или используя в качестве разделителя не пробел а что-то повеселее. Хотя даже так можно RULES подправить и снова будет всё работать.

      Reply
    2. P.S. Post author

      Кстати, PyPy очень хорошо подходит для запуска такого анализатора. Отрабатывает почти на порядок быстрее, чем обычный Python.

      Reply
  2. Иван Семёнов

    Может уже и не ответят мне, но всё же. Вот имеется много строк типа: “Mozilla \”compatible\” MSIE” (т.е. с экранированными кавычками). У меня выводит:
    Mozilla \
    MSIE
    вместо того чтобы вывести всё Mozilla \”compatible\” MSIE. Это как-то обработать можно? пробовал ставить чтобы вырезало только строку где перед кавычкой нет скобки, но не срабатывает: (‘”([^”]+)[^\\\]?”‘, QUOTED_STRING), Я пытался изменить всячески саму регулярку

    Reply
  3. KarelWintersky

    Кстати, можно было бы не писать адские регулярки, а настроить нужный формат лога:

    Это для nginx
    “`
    log_format main ‘$remote_addr – $remote_user [$time_local] “$request” $request_time ‘
    ‘$status $body_bytes_sent “$http_referer” ‘
    ‘”$http_user_agent” “$server_addr” “$http_x_forwarded_for”‘;
    “`
    для апача тоже можно.

    Reply
  4. Sexologist in Delhi

    I think your blog is very informative content. I like the way that you break down complex topics into easy to understand language. You also have a great layout and design. I’m sure other readers will appreciate your work as well. Keep up the great work!

    Reply

Leave a Reply to Иван Семёнов Cancel reply

Your email address will not be published. Required fields are marked *