#!/bin/sh

В преддверии первой годовщины последнего осеннего перевода часов в России вспомнился один факап трехлетней давности (начало 2008 года). Я тогда занимался починкой статистики посещаемости на одном региональном сайтике, который я поддерживал по дружбе.

У них было два сервера, один в интернете показывал контент посетителям, а второй располагался в офисе и содержал интерфейс администрирования сайта. Все хозяйство работало под FreeBSD 6.1 на очень стареньких машинах, на основном сервере был Pentium 3 и 384 мегабайта памяти (однако много лет назад о такой конфигурации можно было лишь помечтать). Apache 2.2.2 вёл лог посещений в режиме «combined», а по ночам всё накопленное за последние сутки обрабатывалось штатной программкой logresolve (преобразовывает IP-адреса посетителей в имена хостов) и копировалось в отдельный файл resolved.log. Затем офисный сервер забирал получившийся файл по HTTP (в целях безопасности все «альтернативные» способы обмена файлами решили не использовать) и парсил его awstats’ом. Такая вот нехитрая схемка. Но проработала она ровно два месяца до середины декабря 2006 года и перестала.

Кроме нескольких программных ошибок обнаружилось еще пара стратегических провалов. Во-первых, офисный сервер иногда отключался из-за проблем с электричеством, и лог не забирался вовремя, а на следующий день просто дополнялся; после двух-трёх пропущенных дней файл с логами разросся до таких размеров, что даже в сжатом виде слишком долго передавался бы по http, и забирающий скрипт просто отваливался по таймауту. Во-вторых, установленный там logresolve натурально портил логи: читал из строки первые 1024 байта, обрабатывал IP-адрес и печатал их в STDOUT, завершив переводом строки; затем читались следующие 1024 байта и т.д. В результате строки, содержащие, например, длинные реферрерские URL, оказались разбитыми на несколько строк по 1024 байта каждая, что, возможно, не имело значения для awstats, но крайне затрудняло дополнительную обработку такого лога.

В итоге с декабря 2006 года лог-файл увеличился в размерах до полутора гигабайт. Я решил, что лучше его разбить на месяцы и скормить эти месяцы парсеру поочерёдно, однако сначала нужно было разобраться с лишними разрывами строк. Быстренько набросал однострочник на sed, который удаляет лишние переводы строк, если в третьем поле не содержится даты.

Однако несмотря на то, что на как на небольших, так и на довольно больших отрывках resolved.log данный скриптик отрабатывал относительно нормально, из реального лога читались только первые 170 мегабайт с копейками и скрипт надолго зависал. Решил, что, возможно, чего-то не учёл из-за малого опыта написания такого рода сценариев на sed, и переделал тот же самый алгоритм на perl и c — безуспешно: после прочтения первых 170 мегабайт ничего не происходило.

my $b='';
while(<>){
        chomp;
        if(/\[[0-9]+\/[a-zA-Z]+\/[0-9:]+\ \+0300\]/){
                print "$b\n";
                $b=$_;
        } else {
                $b.=$_
        }
}
print "$b\n";

Я несколько раз прогнал эти скрипты через valgrind с максимальными проверками утечек, избавился от некоторых ошибок, в конце концов перечитал кучу документации по freebsd на тему возможных ограничений на размер процесса в памяти (хотя больше восьми килобайт программа в памяти не занимала) и т.д. В общем, на два дня выпал из жизни, проводя это время в отладке…

В конце концов нашел причину моих мучений: в регулярном выражении, определявшем признак начала записи лога, была жестко прописана временная зона +0300, тогда как при переходе на летнее время она изменялась на +0400. Поэтому, когда цикл доходил до марта 2007 года, несколько сотен тысяч строк до следующего октября просто пропускались, а поскольку сервер был медленный, то на Ctrl+C и kill -TERM скрипты реагировали не сразу, и тем создавалось ощущение зависания.

После того, как я исправил этот регэксп, всё пошло как по маслу: скормил awstats’у старые логи, прикрутил logrotate, научил скрипты забирать статистику через scp; параллельно крону поставил anacron, благодаря чему забор и анализ логов стал производиться ежедневно вне зависимости от того, включен ли «офисный» сервер в 4 часа 15 минут утра. А потом и вовсе уговорил начальство поставить внешние счетчики. Теперь там стоит google analytics и все счастливы, а я немного прокачал скилл профайлинга.