Как работать с логами Zimbra OSE

Логирование всех происходящих событий — одна из наиболее важных функций любой корпоративной системы. Логи позволяют решать возникающие проблемы, проводить аудит работы информационных систем, а также расследовать инциденты информационной безопасности. Zimbra OSE также ведет подробные логи своей работы. В них попадают все данные от производительности сервера до отправки и получения писем пользователями. Однако чтение логов, генерируемых Zimbra OSE, является довольно нетривиальной задачей. В этой статье на конкретном примере мы расскажем вам о том, как читать логи Zimbra OSE, а также о том, как сделать их централизованными.

Все локальные логи Zimbra OSE хранит в папке /opt/zimbra/log, также логи можно найти в файле /var/log/zimbra.log. Наиболее важным из них является mailbox.log. В нем фиксируются все действия, которые происходят почтовом сервере. Среди них передача писем, данные об аутентификации пользователей, неудачные попытки входа и другие. Записи в mailbox.log представляют из себя текстовую строку, в которой содержится время, в которое произошло событие, уровень события, номер потока, в рамках которого происходило событие, имя пользователя и его ip-адрес, а также текстовое описание события.

Уровень лога означает степень влияния события на работу сервера. По умолчанию используется 4 уровня событий: INFO, WARN, ERROR и FATAL. Разберем все уровни по возрастанию их серьезности.

• INFO — события на этом уровне обычно призваны информировать о ходе работы Zimbra OSE. Среди сообщений этого уровня отчеты о создании или удалении почтового ящика и так далее
• WARN — события этого уровня информируют о ситуациях, которые являются потенциально опасными, но на работе сервера не сказываются. Уровнем WARN например помечается сообщение о неудачной попытке входа пользователя.
• ERROR — этот уровень события в логе информирует о возникновении ошибки, которая носит локальный характер и не препятствует работе сервера. Таким уровнем может быть помечена ошибка, при которой индексные данные отдельного пользователя оказались повреждены.
• FATAL — этим уровнем отмечаются ошибки, из-за которых сервер не может продолжать нормально работать. Например уровень FATAL будет у записи о невозможности подключиться к СУБД.

Файл с логами почтового сервера обновляется каждый день. Свежая версия файла всегда имеет имя Mailbox.log, в то время как логи за определенное число имеют дату в названии и содержатся в архиве. Например mailbox.log.2020-09-29.tar.gz. Благодаря этому значительно упрощается резервирование журналов действий и поиск по логам.

Для удобства системного администратора в папке /opt/zimbra/log/ содержатся и другие логи. В них включены только те записи, которые относятся к конкретным элементам Zimbra OSE. Например в audit.log содержатся исключительно записи об аутентификации пользователей, в clamd.log данные о работе антивируса и так далее. Кстати, отличным методом защиты сервера Zimbra OSE от злоумышленников является защита сервера с помощью Fail2Ban, которая как раз работает на основе audit.log. Также хорошей практикой является добавление cron-задачи на выполнение команды grep -ir „invalid password“ /opt/zimbra/log/audit.log, чтобы ежедневно получать информацию о случаях неудачных попыток входа.

Пример того, как в логе audit.log отображаются дважды неверно введенный пароль и успешная попытка входа

Логи в Zimbra OSE могут быть крайне полезны при выяснении причин различных критических сбоев. В момент, когда происходит критическая ошибка, администратору обычно не до чтения логов. Требуется как можно скорее восстановить работу сервера. Однако потом, когда сервер вновь работает и генерирует множество логов, найти нужную запись в большом файле бывает непросто. Для того, чтобы быстро найти запись об ошибке, достаточно знать время, в которое сервер был повторно запущен и найти в логах запись датированную этим временем. Предшествующая запись и будет являться записью о произошедшей ошибке. Также можно найти сообщение об ошибке с помощью поиска по ключевому слову FATAL.

Также логи Zimbra OSE позволяют выявлять и некритичные сбои. Например для того, чтобы найти исключения обработчика, можно осуществить поиск по фразе handler exception. Нередко ошибки, которые генерирует обработчики сопровождаются трассировкой стека, в которой поясняется, что стало причиной возникновения исключения. В случае ошибок с доставкой почты стоит начать поиски с ключевого слова LmtpServer, а для поиска ошибок связанных с протоколами POP или IMAP можно использовать ключевые слова ImapServer и Pop3Server.

Также логи могут помочь при расследовании инцидентов информационной безопасности. Рассмотрим конкретный пример. 20 сентября один из сотрудников отправил клиенту зараженное вирусом письмо. В результате данные на компьютере клиента оказались зашифрованы. Однако сотрудник клянется, что он ничего не отправлял. В рамках расследования инцидента служба безопасности предприятия запрашивает у системного администратора логи почтового сервера за 20 сентября, связанные с пользователем, в отношении которого проводится расследование. Благодаря временной отметке системный администратор находит нужный файл с логами, извлекает нужную информацию и передает её безопасникам. Те, в свою очередь, просматривают её и обнаруживают, что IP-адрес, с которого было отправлено данное письмо соответствует IP-адресу компьютера пользователя. Записи камер видеонаблюдения подтвердили, что работник во время отправки письма находился на своем рабочем месте. Этих данных хватило для того, чтобы обвинить его в нарушении правил информационной безопасности и уволить. 

Пример извлечения записей об одной из учетных записей из лога Mailbox.log в отдельный файл

Всё значительно усложняется в тот момент, когда речь идет о многосерверной инфраструктуре. Поскольку логи собираются локально, работать с ними в условиях мультисерверной инфраструктуры очень неудобно и поэтому возникает необходимость централизации сбора логов. Сделать это можно за счет настройки хоста для сбора логов. Особой необходимости добавлять в инфраструктуру выделенный хост нет. В качестве узла для сбора логов может выступать любой почтовый сервер. В нашем случае это будет узел Mailstore01.

На этом сервере нам необходимо ввести приведенные ниже команды:

sudo su – zimbra 
zmcontrol stop
exit
sudo /opt/zimbra/libexec/zmfixperms -e -v

Отредактируйте файл /etc/sysconfig/rsyslog, и установите параметр SYSLOGD_OPTIONS=”-r -c 2″

Отредактируйте /etc/rsyslog.conf и раскомментируйте следующие строки:
$ModLoad imudp
$UDPServerRun 514

Введите следующие команды:

sudo /etc/init.d/rsyslog stop
sudo /etc/init.d/rsyslog start
sudo su – zimbra
zmcontrol start
exit
sudo /opt/zimbra/libexec/zmloggerinit
sudo /opt/zimbra/bin/zmsshkeygen
sudo /opt/zimbra/bin/zmupdateauthkeys

Проверить, что все работает можно с помощью команды zmprov gacf | grep zimbraLogHostname. После исполнения команды должно отобразиться имя хоста, который осуществляет сбор логов. Для того, чтобы его изменить, необходимо ввести команду zmprov mcf zimbraLogHostname mailstore01.company.ru.

На всех остальных серверах инфраструктуры (LDAP, MTA и других почтовых хранилищах) выполните команду zmprov gacf |grep zimbraLogHostname, чтобы увидеть название хоста, на которые уходят логи. Чтобы его изменить также можно ввести команду zmprov mcf zimbraLogHostname mailstore01.company.ru

Также на каждом сервере необходимо ввести следующие команды:

sudo su - zimbra
/opt/zimbra/bin/zmsshkeygen
/opt/zimbra/bin/zmupdateauthkeys
exit
sudo /opt/zimbra/libexec/zmsyslogsetup
sudo service rsyslog restart
sudo su - zimbra
zmcontrol restart

После этого все логи будут записываться на указанном вами сервере, где их можно будет удобно просматривать. Также в консоли администратора Zimbra OSE на экране с информацией о состоянии серверов, запущенная служба Logger будет отображаться только у сервера mailstore01.

Еще одной головной болью для администратора может стать отслеживание определенного электронного сообщения. Поскольку электронные письма в Zimbra OSE проходят сразу несколько различных событий: проверка антивирусом, антиспамом и так далее, перед тем как быть принятыми или отправленными, для администратора, в случае если электронное письмо не доходит, может быть достаточно проблематично проследить, на каком этапе оно потерялось.

Для того, чтобы решить эту проблему, можно воспользоваться специальным скриптом, который разработан специалистом по информационной безопасности Виктором Духовным и рекомендован для использования разработчиками Postfix. Данный скрипт конкатенирует записи из логов по определенному процессу и за счет этого позволяет быстро отобразить все записи, связанные с отправкой того или иного письма на основе его идентификатора. Его работа протестирована на всех версиях Zimbra OSE, начиная с 8.7. Приводим текст скрипта.

#! /usr/bin/perl

use strict;
use warnings;

# Postfix delivery agents
my @agents = qw(discard error lmtp local pipe smtp virtual);

my $instre = qr{(?x)
	A			# Absolute line start
	(?:S+ s+){3} 		# Timestamp, adjust for other time formats
	S+ s+ 		# Hostname
	(postfix(?:-[^/s]+)?)	# Capture instance name stopping before first '/'
	(?:/S+)*		# Optional non-captured '/'-delimited qualifiers
	/			# Final '/' before the daemon program name
	};

my $cmdpidre = qr{(?x)
	G			# Continue from previous match
	(S+)[(d+)]:s+	# command[pid]:
};

my %smtpd;
my %smtp;
my %transaction;
my $i = 0;
my %seqno;

my %isagent = map { ($_, 1) } @agents;

while (<>) {
	next unless m{$instre}ogc; my $inst = $1;
	next unless m{$cmdpidre}ogc; my $command = $1; my $pid = $2;

	if ($command eq "smtpd") {
		if (m{Gconnect from }gc) {
			# Start new log
			$smtpd{$pid}->{"log"} = $_; next;
		}

		$smtpd{$pid}->{"log"} .= $_;

		if (m{G(w+): client=}gc) {
			# Fresh transaction 
			my $qid = "$inst/$1";
			$smtpd{$pid}->{"qid"} = $qid;
			$transaction{$qid} = $smtpd{$pid}->{"log"};
			$seqno{$qid} = ++$i;
			next;
		}

		my $qid = $smtpd{$pid}->{"qid"};
		$transaction{$qid} .= $_
			if (defined($qid) && exists $transaction{$qid});
		delete $smtpd{$pid} if (m{Gdisconnect from}gc);
		next;
	}

	if ($command eq "pickup") {
		if (m{G(w+): uid=}gc) {
			my $qid = "$inst/$1";
			$transaction{$qid} = $_;
			$seqno{$qid} = ++$i;
		}
		next;
	}

	# bounce(8) logs transaction start after cleanup(8) already logged
	# the message-id, so the cleanup log entry may be first
	#
	if ($command eq "cleanup") {
		next unless (m{G(w+): }gc);
		my $qid = "$inst/$1";
		$transaction{$qid} .= $_;
		$seqno{$qid} = ++$i if (! exists $seqno{$qid});
		next;
	}

	if ($command eq "qmgr") {
		next unless (m{G(w+): }gc);
		my $qid = "$inst/$1";
		if (defined($transaction{$qid})) {
			$transaction{$qid} .= $_;
			if (m{Gremoved$}gc) {
				print delete $transaction{$qid}, "n";
			}
		}
		next;
	}

	# Save pre-delivery messages for smtp(8) and lmtp(8)
	#
	if ($command eq "smtp" || $command eq "lmtp") {
		$smtp{$pid} .= $_;

		if (m{G(w+): to=}gc) {
			my $qid = "$inst/$1";
			if (defined($transaction{$qid})) {
				$transaction{$qid} .= $smtp{$pid};
			}
			delete $smtp{$pid};
		}
		next;
	}

	if ($command eq "bounce") {
		if (m{G(w+): .*? notification: (w+)$}gc) {
			my $qid = "$inst/$1";
			my $newid = "$inst/$2";
			if (defined($transaction{$qid})) {
				$transaction{$qid} .= $_;
			}
			$transaction{$newid} =
				$_ . $transaction{$newid};
			$seqno{$newid} = ++$i if (! exists $seqno{$newid});
		}
		next;
	}

	if ($isagent{$command}) {
		if (m{G(w+): to=}gc) {
			my $qid = "$inst/$1";
			if (defined($transaction{$qid})) {
				$transaction{$qid} .= $_;
			}
		}
		next;
	}
}

# Dump logs of incomplete transactions.
foreach my $qid (sort {$seqno{$a} <=> $seqno{$b}} keys %transaction) {
    print $transaction{$qid}, "n";
}

Cкрипт написан на Perl и для его запуска необходимо сохранить его в файл collate.pl, сделать его исполняемым, а затем запустить файл с указанием файла логов и с помощью pgrep выделить идентификационную информацию искомого письма collate.pl /var/log/zimbra.log | pgrep ‘<20200929164500.user@mail.company.ru>’. Результатом станет последовательный вывод строк, в которых содержится информация о движении письма на сервере.

# collate.pl /var/log/zimbra.log | pgrep '<20200929101700.user@mail.company.ru>'
Oct 13 10:17:00 mail postfix/pickup[4089]: 4FF14284F45: uid=1034 from=********
Oct 13 10:17:00 mail postfix/cleanup[26776]: 4FF14284F45: message-id=*******
Oct 13 10:17:00 mail postfix/qmgr[9946]: 4FF14284F45: from=********, size=1387, nrcpt=1 (queue active)
Oct 13 10:17:00 mail postfix/smtp[7516]: Anonymous TLS connection established to mail.*******[168.*.*.4]:25: TLSv1 with cipher ADH-AES256-SHA (256/256 bits)
Oct 13 10:17:00 mail postfix/smtp[7516]: 4FF14284F45: to=*********, relay=mail.*******[168.*.*.4]:25, delay=0.25, delays=0.02/0.02/0.16/0.06, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 878833424CF)
Oct 13 10:17:00 mail postfix/qmgr[9946]: 4FF14284F45: removed
Oct 13 10:17:07 mail postfix/smtpd[21777]: connect from zimbra.******[168.*.*.4]
Oct 13 10:17:07 mail postfix/smtpd[21777]: Anonymous TLS connection established from zimbra.******[168.*.*.4]: TLSv1 with cipher ADH-AES256-SHA (256/256 bits)
Oct 13 10:17:08 mail postfix/smtpd[21777]: 0CB69282F4E: client=zimbra.******[168.*.*.4]
Oct 13 10:17:08 mail postfix/cleanup[26776]: 0CB69282F4E: message-id=zimbra.******
Oct 13 10:17:08 mail postfix/qmgr[9946]: 0CB69282F4E: from=zimbra.******, size=3606, nrcpt=1 (queue active)
Oct 13 10:17:08 mail postfix/virtual[5291]: 0CB69282F4E: to=zimbra.******, orig_to=zimbra.******, relay=virtual, delay=0.03, delays=0.02/0/0/0.01, dsn=2.0.0, status=sent (delivered to maildir)
Oct 13 10:17:08 mail postfix/qmgr[9946]: 0CB69282F4E: removed

По всем вопросам, связанными c Zextras Suite вы можете обратиться к Представителю компании «Zextras» Екатерине Триандафилиди по электронной почте katerina@zextras.com

Источник: habr.com