Python → Как правильно распарсить 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 адреса.