Давно меня заботила проблема, что пользователь шаред-хостинга не всегда знает, что происходит с его аккаунтом — зашёл ли кто по ftp, выполнилось ли задание cron, был ли доступ по ssh, куда делось письмо и вообще отправлялось ли. У большинства хостеров (и у нас в том числе) пользователь мог задать вопрос в службу техподдержки и ждать, когда специалист с соответствующими правами и квалификацией сделает подборку нужных логов. Бонусная проблема — нельзя вот так просто взять и одной командой посмотреть записи в логах относящиеся к пользователю. Это создаёт трудности для системного администратора.Казалось бы простая задача с самого начала начала преподносить сюрпризы.
Во-первых, оказалось, что не все программы умеют работать с системой syslog. Например, proftpd умеет писать основной журнал в syslog, но не умеет писать туда журнал работы с файлами. В документации есть “костыль” для этой ситуации (кстати, неработающий), подразумевающий отдельного “демона”, слушающего FIFO-файл (в который внезапно proftpd умеет писать любой журнал). Но записи в журнал в итоге идут странные и по сумме подпорок я решил отказаться от идеи писать фильтр, запускаемый из syslogd.
Во-вторых, оказалось, что для некоторых программ следует вводить “следяющую” систему (которая сохраняет строки, и пишет их в журнал только при появлении строки, позволяющей идентифицировать пользователя) с нетривиальным анализом строк журнала. Самый бедный журнал у сервера OpenSSH. Чтобы понять под каким ключом залогинился пользователь, приходится включать режим отладки, подключение к терминалу пишется только в режиме самой сильной отладки (и я отказался), туннели вообще никак особым образом не выделяются. Ключ в журнал пишется не сам, а fingerprint (скажите, сколько из читающих это вот так сходу сможет посмотреть fingerprint ssh-ключа?), пришлось писать подпорку, пишущую в журнал начало и конец ключа из authorized_keys, чтобы было понятно. Установленные соединения не имею идентификатора и приходится запоминать их по pid процесса, после успешного логина журнал не помечается именем пользователя и опять приходится держать в памяти какой pid обслуживает какого пользователя. Приходится внимательно следить за всеми возможными вариантами завершения процесса во избежании “утечек” или неверных интерпретаций. В том числе я написал “сборщик мусора”, учитывая, что некоторые строки журнала я могу случайно “потерять”. Проблемой трудно отслеживаемого соединения обладает и журнал proftpd. Самым простым как ни странно оказался sendmail. Он всем письмам проставляет номер очереди, которую обязательно пишет в журнал. Везде, где это уместно, он сообщает с каким именно системным пользователем он имел дело. При этом сам формат журнала у sendmail немного мозголомный.
Процесс реализации “раскладывалки” после выяснения особенностей и выбора способа чтения логов тоже оказался занимательным.
Решил я пойти согласно идеологии UNIX использовать уже имеющиеся инструменты. Саму “раскладывалку” я традиционно писал на perl, задача стояла в отслеживании журналов. Выбор пал на утилиту tail с ключем -f на каждый интересующий журнал и последующий разбор считанного. Но что делать с ротацией логов, которые читаем? И тут на старости лет мне открыли глаза на ключ -F. Для простоты я решил сделать по процессу на каждый журнал… и “умер” на диспетчеризации процессов. При поступлении внешнего сигнала надо сигнал послать каждому, у того должны быть свои обработчики, надо отработать падение системы, перезагрузку. И тут я вспомнил, что tail умеет следить за несколькими файлами одновременно. Составление алгоритмов определения к какому файлу относится какая строка оказалось нетривиальным. ‘tail’ пишет, из какого файла он в данный момент выводит строки, но приходится делать следящую систему, запоминающую, что он написал. После полудня мучений, оказалось, что в системной реализации tail во FreeBSD ошибка, он при работе не с терминалом название файла пишет после вывода строк из него, а не перед. В итоге я просто сделал собственную реализацию непрерывного чтения файлов на языке Perl с отслеживанием их переименования. К вопросу о велосипедах и стандартных решениях. Иногда велосипед по всем параметрам выгоднее.
Как я сделал ротацию пользовательских логов? Как и ротацию остальных — этим занимается системная утилита. При получении строки для журнала пользователя, скрипт “раскладывалки” смотрит, если ли у меня такой в открытых файлах, если нет, то открывает и запоминает. Системный сервис ротации логов после переименования и ротации пользовательских логов посылает классических SIGHUP нашей “раскладывалке”. Обработчик этого сигнала в “раскладывалке” просто чистит список открытых дескрипторов, попутно закрывая их. Соответственно, при поступлении данных файлы открываются заново.
Результат оказался впечатляющим. Столько всего интересного оказалось в поведении пользователей. И к слову о приятных дополнениях, украшающих любую хорошую утилиту. Кроме раскладывания логов в домашние каталоги пользователей, я сделал копию записи отдельно в одном месте для системных администраторов. Теперь можно одним взглядом оценить текущую ситуацию у каждого пользователя по интересующему сервису. Журналы в дополнительном месте при ротации просто убиваются, так как для текущей оценки не требуется архив.
Резюме. Когда вы пишете программу, думайте, для кого вы пишите логи этой программы. Когда вы выбираете некий инструмент, подумайте — а точно это не идеологический выбор?
P.S. Выражаю огромную благодарность моим читателям на Juick за помощь в разработке системы. Без вас были все шансы не справиться с задачей.
UPDATE: github.com/schors/peruserlog
