У меня есть несколько сервисов, которыми я владею, которые работают в EC2, но, к сожалению, по-прежнему не хватает агрегирования журналов. Для этого у нас есть собственная система, которая технически может также работать в EC2, но по ряду причин я считаю ее излишней для моего варианта использования в EC2. По сути, решение, которое мне нужно, — это выполнить минимальный объем работы, чтобы увидеть эти журналы, агрегированные в корзину S3, и сделать их доступными для дополнительной обработки позже с Elastic MapReduce, если нам когда-либо понадобится выполнить какой-либо анализ. Такое случается редко, поэтому текущее решение распределенной команды SSH, копирующей журналы активных машин, в основном достаточно. Если интересующие вас журналы попали на компьютер, который был прерван в результате действия по уменьшению группы AutoScale, то это именно то, что решило бы объединение журналов!
Реальные сервисы, работающие в этих экземплярах, обычно работают через Upstart. Несмотря на результаты недавних Init Wars в сообществе Debian, я считаю, что Upstart является приемлемой системой Init и, безусловно, достаточно прост в настройке — поместите файл conf в разумно минимальном формате в / etc / init, и все готово. В достаточно недавних версиях (1.4 и более поздних) вы можете даже заставить Upstart позаботиться о ведении журнала в файл для вас, и, соответственно, (поскольку он удаляет фрагмент logrotate в вашу систему), он также обрабатывает logrotation. Однако, если вы будете читать официальную документацию по Upstart, вы будете прощены за то, что думаете, что механизм регистрации несколько волшебен, так как не так много подробностей.
Почему я заинтересован в этом? Мне пришлось освежить мою память об этом, но, конечно, логротация происходит не чаще одного раза в день (она запускается из cron.daily). Для моих служб, работающих в группах AutoScale, некоторые экземпляры длятся менее 24 часов, поэтому я бы предпочел агрегировать свои журналы как минимум каждый час. Не зная точных отношений между Upstart и logrotate, трудно сказать, возможно ли это. Мое намерение состоит в том, чтобы каждый час запускать какую-то другую небольшую задачу cron, чтобы вытащить журнал из использования Upstart (как бы то ни было), добавить метку времени и информацию о машине к имени файла, сжать ее и загрузить в корзину S3 , Когда начать?
Возвращаясь к первоначальному сообщению в списке рассылки для разработчиков за октябрь 2011 г., приведем некоторые подробности. Как и в документации, на которую ссылается Upstart, она создает псевдотерминал и подключает подчиненное устройство к дочернему процессу и ведущее устройство к себе. Это происходит в init / job_process.c , который стоит прочитать, чтобы понять, что происходит. Upstart действительно берет на себя всю обработку регистрации, а не делегирование внешнему процессу. Давайте подтвердим, что наш процесс действительно не пишет сам журнал:
# service testprogram start testprogram start/running, process 27671 # lsof -n -p 27671 | tail -n4 testprogr 27671 root 0u CHR 1,3 0t0 4759 /dev/null testprogr 27671 root 1u CHR 136,1 0t0 4 /dev/pts/1 testprogr 27671 root 2u CHR 136,1 0t0 4 /dev/pts/1 testprogr 27671 root 255r REG 252,0 341 275311 /usr/local/bin/testprogram
ОК, он определенно подключен к псевдотерминалу для стандартного вывода и стандартной ошибки. Процесс init подключен к файлу журнала?
# lsof -p 1 | grep testprogram init 1 root 11w REG 252,0 3086869601 10521 /var/log/upstart/testprogram.log
Большой! Итак, теперь мы знаем, что если мы хотим выяснить семантику ротации логов, нам не нужно беспокоиться о нашем собственном процессе — только о самом Upstart. Так как же взаимодействуют Upstart и logrotate? Фрагмент logrotate дает очень мало:
/var/log/upstart/*.log {
daily
missingok
rotate 7
compress
notifempty
nocreate
}
Он не делает ничего особенного, чтобы сообщить Upstart о том, что журналы были повернуты, например, в скрипте prerotate или postrotate. Посмотрев в инициализации / log.c вы можете увидеть , что Upstart Работа содержит объект журнала , который знает о файле журнала консоли , которая была использована для этой конкретной услуги. Он сохраняет дескриптор файла открытым, так что любые новые данные, поступающие из сервиса, могут быть просто записаны прямо в файл. Существует некоторая дополнительная информация об условиях вне диска, и некоторая буферизация, выполняемая утилитарной библиотекой NIH, но они ортогональны проблеме ротации журналов.
Когда поступает какой-то ввод, Upstart пытается сбросить данные на диск и в процессе проверяет состояние дескриптора файла, который он уже открыл (с помощью системного вызова fstat). Если результат fstat указывает на отсутствие ссылок на файл (т. Е. Он был удален, но он все еще открыт), Upstart откроет новый файл с тем же именем и сбросит данные журнала в этот файл. Следовательно, когда logrotate поворачивает файл с новым именем, ничего не происходит. Но поскольку фрагмент конфигурации Upstart logrotate содержит директиву compress , он вызовет gzip, который удалит исходный файл, как только новый сжатый файл будет полностью записан. Upstart обнаружит удаление, откроет новый файл и продолжит регистрацию. Тайна разгадана!
Как это выглядит в действии? Я сделал очень простой сценарий оболочки, который выводит пару фраз и номер строки в тесном цикле, чтобы проверить поведение вращения и потери в журнале Upstart, а также сколько данных теряется между завершением сжатия gzip и открытием нового файл. Первоначально я также добавил в сценарий несколько сигнальных ловушек, чтобы посмотреть, не делает ли там Upstart что-то необычное (например, отправляет сигнал зависания), но, поскольку сама программа не регистрирует, ей не требуется никакой сигнализации, чтобы быть в курсе механизм каротажа:
#!/bin/bash -e
let i=1
while true; do
echo "${i} The quick brown fox jumped over the lazy dog. She sells seashells by the sea shore. The shells she sells are seashells I'm sure."
let i=i+1
done
Поскольку между циклами не спит, это выполняется так быстро, как данные могут быть приняты на псевдотерминале. Очевидно, это также вызывает некоторую нагрузку на сам Upstart:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27754 root 20 0 17856 1484 1236 R 46.3 0.1 0:03.62 testprogram
1 root 20 0 24380 2220 1296 S 45.6 0.1 15:36.35 init
Вы можете увидеть, что делает Upstart со strace:
select(15, [3 5 6 7 8 9 12 14], [], [7 8 9 12], NULL) = 1 (in [14])
read(14, "\r\n1403895 The quick brown fox ju"..., 8192) = 552
read(14, "\r\n1403899 The quick brown fox ju"..., 7640) = 138
read(14, 0x7f1027c3fbf2, 7502) = -1 EAGAIN (Resource temporarily unavailable)
fstat(11, {st_mode=S_IFREG|0640, st_size=192626266, ...}) = 0
write(11, "\r\n1403895 The quick brown fox ju"..., 690) = 690
read(3, 0x7fff293210ff, 1) = -1 EAGAIN (Resource temporarily unavailable)
waitid(P_ALL, 0, {}, WNOHANG|WEXITED|WSTOPPED|WCONTINUED, NULL) = 0
Таким образом, он ожидает вызова select, чтобы указать, что одно из его заданий имеет какой-то вывод, выполняет некоторые операции чтения для сбора этого вывода из псевдотерминала, выполняет fstat для файла и затем записывает буферизованные данные за один вызов. Что происходит, когда мы удаляем файл между записями?
select(15, [3 5 6 7 8 9 12 14], [], [7 8 9 12], NULL) = 1 (in [14])
read(14, "4 The quick brown fox jumped ove"..., 8192) = 132
read(14, 0x7f1027c3f9c4, 8060) = -1 EAGAIN (Resource temporarily unavailable)
fstat(10, {st_dev=makedev(252, 0), st_ino=10521, st_mode=S_IFREG|0640, st_nlink=0, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=264, st_atime=2014/05/18-20:33:32, st_mtime=2014/05/18-20:33:42, st_ctime=2014/05/18-20:33:48}) = 0
close(10) = 0
umask(0117) = 0117
open("/var/log/upstart/testprogram.log", O_WRONLY|O_CREAT|O_APPEND|O_NONBLOCK|O_NOFOLLOW|O_CLOEXEC, 0740) = 10
write(10, "4 The quick brown fox jumped ove"..., 132) = 132
read(3, 0x7fff293210ff, 1) = -1 EAGAIN (Resource temporarily unavailable)
waitid(P_ALL, 0, {}, WNOHANG|WEXITED|WSTOPPED|WCONTINUED, NULL) = 0
На этот раз я запустил strace с
параметром -v, чтобы полностью расширить вывод системных вызовов. Я замедлил вывод до одной строки за десять секунд, а затем удалил файл сразу после того, как одна строка была записана на диск. Вы можете видеть, что fstat возвращает
st_nlink = 0 , после чего Upstart закрывает дескриптор файла, устанавливает umask, а затем снова открывает файл по имени перед записью буферизованной строки журнала в файл. Отлично, это имеет смысл, но работает ли оно также, когда поступает большой объем данных?
Убрав сон в скрипте, я позволил журналу накопиться примерно до 2 ГБ, прежде чем что-либо делать. Для справки, он записывал в журнал около 3 МБ / с, что не очень много, но, безусловно, достаточно для отдельной службы, даже если она ведет себя плохо Чтобы смоделировать реалистичные условия вращения, я просто вызвал gzip в файле журнала, чтобы позволить ему сжать, а затем удалить исходный файл. Взглянув на конец сжатого файла и начало нового файла (где мы ожидаем увидеть некоторые потери), это результат:
# zcat testprogram.log.gz | tail -n1 18693551 The quick brown fox jumped over the lazy dog. She sells seashells by the sea shore. The shells she sells are seashells I'm sure.# # head -n2 testprogram.log 18693552 The quick brown fox jumped over the lazy dog. She sells seashells by the sea shore. The shells she sells are seashells I'm sure.
Интересно, что символ новой строки удаляется из конца первого файла и заканчивается в начале второго файла, но самое главное, что ни одна строка не была пропущена, и фактически у нас все неповрежденные байты между повернутыми файл и текущий файл. Я не уверен, что это не сломается при более высоких скоростях ведения журнала, и, конечно, Upstart был очень сильно загружен только при таком количестве ведения журнала, но для моих целей, которые могут выдержать некоторые потери, этого, безусловно, достаточно. Еще одна проблема, вызывающая беспокойство, — это высокая частота вызовов fstat (по одному на каждый сброс журнала), которые не влияют на производительность ведения журнала Upstart, однако для низких скоростей ведения журнала это не должно иметь большого влияния.
So the next step is to actually put this into practice, which involves writing a prerotate script that ignores the log files of the services I am interested in (so they don’t get rotated by both logrotate and my own log handling), then write a bit of glue code to compress and upload them to S3 hourly. It may seem like a lot more effort but I’m really trying to avoid another solution that requires external services to manage the logs (e.g. remote syslog, fluentd, Logstash connected to ElasticSearch etc). If this current idea fails or turns out to be more effort than antipated, well, I guess I’ll go down the logging service path instead.