"... Любите ли вы читать логи? Любите ли вы читать логи так, как люблю читать их я ??? ..."
(перефразированный В.Г.Белинский)
03.08.2011.
Здесь я опишу коротенькие и удобные команды и скрипты для быстрого получения информации из почтовых логов sendmail'a.
Навеяно вот этой задачкой - "Как заблокировать письмо, если среди получателей указан определенный пользователь-приманка (honey pot)." В моем /etc/syslog.conf на почтовом сервере есть такая строка:
*.* /dev/tty12
Однажды, переключившись на этот терминал, я увидела постоянно мелькающие имена пользователей-ловушек в качестве получателей писем (письма были отвергнуты).
Естественно, мне захотелось увидеть полную информацию по этим событиям:
- сколько было таких рассылок за текущий день;
- какой(какие) IP был(и) источником таких писем;
- насколько большим был список получателей (чем больше число получателей, тем больше эффективность honeypot-ловушки).
И вообще захотелось взглянуть на полный отчет по всем процессам, имевшим отношение к honeypot ловушке.
Но сначала небольше отступление. Порой на форумах с удивлением обнаруживаю равнодушие или недопонимание или даже уничижительное
отношение к чтению логов. Даже на sendmail-конфе как-то раз довелось увидеть ответ одного sendmail-гуру, который можно перевести так:
"Не понимаю людей, подробно изучающих логи". Вопрос же касался непонимания автором смысла одной из записей в maillog.
"Эта запись говорит о проблеме или нет? Если да, то с чьей стороны проблема? С моей или с внешней?"-вопрошал автор.
По-моему, разумные вопросы и разумное желание быть в курсе происходящего на твоем сервере.
На сервере, находящемся в зоне твоей ответственности. Особенно, если ты новичок, и многое непонятно и подозрительно.
Через некоторое время состоялась уже другая дискуссия на тему "Анализаторы логов", теперь уже на opennet.ru.
Поскольку ответ уважаемого Lavr'a "глаза + мозги" был вопринят буквально, то пришлось рассказывать о скриптах, "шерстящих" логи,
и о глазах (а как же без них?): быстрый натренированный взгляд на лог всегда выцепит что-то нестандартное и подозрительное. Ведь что такое скрипт?
Это стрельба вдогонку: вы уже знаете, что вот эта запись говорит о том-то и том-то, и поэтому пишете скрипт, отлавливающий подобные записи и принимающий решение.
Но сначала ваши глаза увидят в логе что-то подозрительное, и только потом вы включите второй анализатор - мозги(скрипты).
Итак, возвращаюсь к основной теме статьи.
I.
cat /usr/bin/local/e1 (аналогично e,e2,e3,...)
egrep -i "$1" /var/log/maillog.1
cat /usr/bin/local/sidlook (sendmail ID look)
string="[0-9a-zA-Z]{14}:"
egrep -o "$string"|sort|uniq
Теперь нам нужно быстренько посмотреть, какая почта вчера была отправлена со шлюза 2.1.3.5 !
e1 "`e1 2.1.3.5|egrep sendmail|sidlook`" - найти все записи, содержащие адрес шлюза, из них выбрать sendmail-овские,
из них выбрать номера процессов, и всю инфу по этим процессам мне показать.
На выходе имеем:
Jun 27 13:41:49 mail sendmail[16575]: p5R7fmbv016575: from=<consiglio@anrb.ru>, size=56863, class=0, nrcpts=1, msgid=<532321557.20110627140642@anrb.ru>, proto=ESMTP, daemon=MTA, relay=i.ufaras.ru [2.1.3.5]
Jun 27 13:41:50 mail sendmail[16577]: p5R7fmbv016575: to=<dffffr@mail.ru>, ctladdr=<consiglio@anrb.ru> (1234/10), delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=176863, relay=mxs.mail.ru. [94.100.176.20], dsn=2.0.0, stat=Sent (OK id=1Qb6r1-00058r-00)
и так далее еще куча процессов
Удобно?! Одной строчкой!
II.
Второй пример аналогичен предыдущему по реализации, но отличен по сути.
Некоторые н.с. уезжают работать за границу, но меня не извещают об этом (ес-но!). При этом продолжают пользоваться родной эл. почтой (да здравствует smtp-auth!).
Я отслеживаю внешнее (в данном случае внешнее - это отличное от регионального) использование smtp-auth. Предположим, система отслеживания обнаружила внешнее
подключение к smtp-auth и известила меня об этом. Далее я делаю так:
e "`e 1.2.3.251|sidlook`"|egrep -v "drweb|syslog" и убеждаюсь, что все нормально:
Oct 31 13:27:20 mail sendmail[9394]: p9V7RF8e009394: from=<terrapin@anrb.ru>, size=1482, class=0, nrcpts=1, msgid=<126310043.20111031082349@anrb.ru>, proto=ESMTP, daemon=MTA, relay=[1.2.3.251]
Oct 31 13:27:20 mail sendmail[9396]: p9V7RF8e009394: to=<veuserenko@mail.ru>, ctladdr=<terrapin@anrb.ru> (1162/210), delay=00:00:00, xdelay=00:00:00, mailer=esmtp, pri=121482, relay=mxs.mail.ru. [94.100.176.20], dsn=2.0.0, stat=Sent (OK id=1RKmDr-0008P7-00)
Oct 31 17:45:02 mail sendmail[28718]: p9VBiwQj028718: from=<terrapin@anrb.ru>, size=1444, class=0, nrcpts=1, msgid=<1419227923.20111031124131@anrb.ru>, proto=ESMTP, daemon=MTA, relay=[1.2.3.251]
Oct 31 17:45:03 mail sendmail[28817]: p9VBiwQj028718: to=<veuserenko@mail.ru>, ctladdr=<terrapin@anrb.ru> (1162/210), delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=121444, relay=mxs.mail.ru. [94.100.176.20], dsn=2.0.0, stat=Sent (OK id=1RKqFE-0000Qx-00)
III.
cat /usr/local/bin/iplook (IP look)
string="({0-9]{1,3}\.){3}[0-9]{1,3}"
egrep -o "$string"
Далее. У меня используются т.н. honey-pots - завлекаловки, заманушечки, e-mails, которые я указываю на своих страницах в примерах, потом они попадают в спам-рассылки, и по наличию в списке получателей кого-либо из "медового горшочка" я спокойно блокирую спам.
e terrapin - посмотреть всю инфу с участием "горшочка с медом" за сегодняшний день.
Тут будут лишь строки с to=<terrapin@anrb.ru>. Этого мне мало. Хочу посмотреть, насколько "горшочки" эффективны: сколько получателей по каждому процессу, а следовательно, и отказов. Еще интересны IP источников спама.
e terrapin|sidlook - давай-ка мне все sendmail PID из этой серии!
e "`e terrapin|sidlook`" - а теперь всю информацию по всем процессам!!
e "`e terrapin|sidlook`"|iplook|sort|uniq - и хочу знать все IP, которые клюнули на мед !!!
А теперь посмотрю, какая вообще активность с этих IP?
e `e "\`e terrapin|sidlook\`"|iplook|sort|uniq`
А дальше однострочная красота уже не работает, поэтому пишем скрипт и получаем информацию по всем процессам, инициированным IP, клюнувшими на мед:
e `e "\`e terrapin|sidlook\`"|iplook`|sort|uniq|sidlook >tmp_sid
for sid in `cat tmp_sid` ; do
echo $sid
egrep "$sid" /var/log/maillog
echo
done
А вот как можно посмотреть полную историю про все процессы, имевшие отношение ко всем honey-pots:
e "Текст отказа в конфиге для honey-pot проверки"
e "Текст отказа в конфиге для honey-pot проверки"|sidlook
e "`e 'Текст отказа в конфиге для honey-pot проверки'|sidlook`"
Для чего здесь нужны кавычки, объясню в след раз.
IV.
10.04.2012. Вижу в отчете DrWeb следующее:
*** Plug-in vaderetro ***
Top 20 of blocked objects:
MailD processing error - 1 ( 100% )
Top 20 of blocked senders: - 1 ( 100% )
Top 20 blocked IP addresses: 1.2.3.4 (адрес моей сети) - 1 ( 100% )
Ackhtung! Ackhtung! Was ist das?
e1 `e1 1.2.3.4|sidlook`
Apr 9 12:34:15 mail sendmail[4158]: q396YE7f004158: from=<consiglio@ anrb.ru>, size=1454, class=0, nrcpts=1, msgid=<39DE8859F85C4F1B9831ED42A85AE7BE@LocalHost>, proto=SMTP, daemon=MTA, relay=[1.2.3.4]
Apr 9 12:34:15 mail drweb-milter.real: [2844142448] milter INFO 0003FA0E/q396YE7f004158 success save mail to /var/drweb/msgs/in/E/0003FA0E/
Apr 9 12:34:15 mail drweb-maild.real: [2989099888] maild ERROR 0003FA0E/q396YE7f004158 enqueue thread error: message enqueue failed: read(/var/drweb/msgs/in/E/0003FA0E/.envelope) error: wrong char in e-mail address [<consiglio@ anrb.ru>]
Apr 9 12:34:15 mail drweb-maild.real: [2989099888] maild WARN 0003FA0E/q396YE7f004158 processing msg on event: processing error for 3fa0e, apply: [pass]
Apr 9 12:34:15 mail drweb-milter.real: [2844142448] milter INFO 0003FA0E/q396YE7f004158 drweb-maild return pass action. score=0
Apr 9 12:34:15 mail drweb-milter.real: [2844142448] milter INFO 0003FA0E/q396YE7f004158 processing message [from: <consiglio@ anrb.ru>; to:<12bnd0577@domain.ru>] is over
Apr 9 12:34:15 mail sendmail[4160]: q396YE7f004158: syslog:LCR02:consiglio<@anrb.ru.>
Apr 9 12:34:15 mail sendmail[4160]: q396YE7f004158: syslog:LCR02:12bnd0577<@domain.ru.>
Apr 9 12:34:16 mail sendmail[4160]: q396YE7f004158: to=<12bnd0577@domain.ru>, ctladdr=<consiglio@ anrb.ru> (1426/210), delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=121454, relay=mail4.domain.ru. [5.9.0.7], dsn=2.0.0, stat=Sent (Ok: queued as 50DCC1200B0)
Ок, ничего страшного: пользователь поставил пробел после @, что заметил DrWeb и отреагировал.
На этом пока вынуждена прерваться.
ПРодолжение следует.
А вообще еще одной причиной для написания данной статьи является попытка добиться правильного показа выдержек из лога от авторов вопросов на форумах.
Почему-то народ предпочитает вырезать кусок лога по принципу общего для записей времени, но никак не общего номера процесса.
Чем при этом этом этот народ думает - непонятно ....
Вопрос предполагаемой мной неоптимальности использования ресурсов компа при исполнении таких команд пока оставляю открытым,
но главное в этих примерах - это возможность быстрого получения полной информации. А для дальнейшего статистического исследования какого-либо события
можно и скрипт написать. Потом. Красивый, логичный, оптимально использующий ресурсы системы.
Обратная связьздесь. Страница задумана (а также описанные команды используются) с полгода назад. Создана 3 августа 2011г. Последнее обновление - 31 октября 2011г.