Hur man arbetar med Zimbra OSE-loggar

Loggning av alla händelser är en av de viktigaste funktionerna i varje företagsystem. Loggar gör det möjligt att hantera uppkomna problem, utföra revision av informationssystemens arbete samt utreda incidenter inom informationssäkerhet. Zimbra OSE håller också detaljerade loggar över sin verksamhet. Dessa innehåller all data från serverns prestanda till avsändning och mottagning av e-post av användarna. Att läsa loggarna som genereras av Zimbra OSE är emellertid en ganska komplicerad uppgift. I denna artikel kommer vi med ett konkret exempel att berätta hur man läser loggarna för Zimbra OSE samt hur man kan centralt hantera dem.

Alla lokala loggar för Zimbra OSE lagras i mappen /opt/zimbra/log, och loggar kan också hittas i filen /var/log/zimbra.log. Den viktigaste av dem är mailbox.log. I den registreras alla åtgärder som sker på e-postservern. Bland dessa finns överföring av e-post, användarautentisering, misslyckade inloggningsförsök och så vidare. Poster i mailbox.log är textsträngar som innehåller tidpunkten för händelsen, händelsens nivå, trådnummer där händelsen ägde rum, användarnamn och dess ip-adress samt en textuell beskrivning av händelsen.

Loggnivån anger graden av påverkan av händelsen på serverns arbete. Som standard används fyra nivåer av händelser: INFO, WARN, ERROR och FATAL. Vi går igenom dessa nivåer i ordning av ökad allvarlighet.

• INFO — händelser på denna nivå är avsedda att informera om Zimbra OSE:s drift. Bland meddelandena på denna nivå finns rapporter om skapande eller radering av e-postlådor och så vidare.
• WARN — händelser på denna nivå informerar om situationer som är potentiellt otrygga men som inte påverkar serverns drift. En WARN-nivå används till exempel för att markera ett meddelande om ett misslyckat inloggningsförsök av en användare.
• ERROR — denna nivå av händelsen i loggen informerar om att ett fel har uppstått som är lokalt och inte hindrar serverns drift. En sådan nivå kan markera ett fel där indexdata för en enskild användare har blivit korrupt.
• FATAL — denna nivå markerar fel som gör att servern inte kan fortsätta fungera normalt. Till exempel kommer en FATAL-nivå att finnas i posten om att det inte går att ansluta till databashanteraren.

Loggfilerna från e-postservern uppdateras varje dag. Den senaste versionen av filen har alltid namnet Mailbox.log, medan loggarna för ett visst datum har datum i namnet och finns i ett arkiv. Till exempel mailbox.log.2020-09-29.tar.gz. Tack vare detta förenklas säkerhetskopiering av aktivitetsloggar och sökning i loggar avsevärt.

För systemadministratörens bekvämlighet finns andra loggar i mappen /opt/zimbra/log/. Dessa loggar innehåller endast de poster som rör specifika delar av Zimbra OSE. Till exempel innehåller audit.log endast poster om användarautentisering, clamd.log innehåller data om antivirusets arbete och så vidare. För övrigt är en utmärkt metod för att skydda Zimbra OSE-servern från intrång att skydda servern med Fail2Ban, som fungerar baserat på audit.log. En god praxis är också att lägga till en cron-uppgift för att köra kommandot grep -ir "invalid password" /opt/zimbra/log/audit.log, för att dagligen få information om misslyckade inloggningsförsök.

Ett exempel på hur en felaktigt inmatad lösenord upprepas två gånger i audit.log samt en lyckad inloggning

Loggarna i Zimbra OSE kan vara ytterst användbara för att ta reda på orsakerna till olika kritiska fel. När en kritisk fel inträffar har administratören vanligtvis inte tid att läsa loggar. Det krävs att servern återställs så snabbt som möjligt. Men senare, när servern fungerar igen och genererar många loggar, kan det vara besvärligt att hitta rätt post i den stora filen. För att snabbt hitta en felpost räcker det att veta tidpunkten då servern startades om och leta efter en post i loggarna som är daterad vid den tiden. Den föregående posten kommer att vara posten om det inträffade felet. Du kan också hitta felmeddelandet genom att söka efter nyckelordet FATAL.

Zimbra OSE-loggarna kan också identifiera icke-kritiska fel. Till exempel, för att hitta undantagshanterare kan man söka efter frasen handler exception. Ofta åtföljs de fel som genereras av hanterarna av en stacktrace som förklarar orsaken till att undantaget uppstod. När det gäller fel med e-postleverans bör man börja sökningen med nyckelordet LmtpServer, och för att söka efter fel relaterade till POP- eller IMAP-protokollen kan man använda nyckelorden ImapServer och Pop3Server.

Loggarna kan också vara till hjälp vid utredningar av informationssäkerhetsincidenter. Låt oss överväga ett konkret exempel. Den 20 september skickade en av de anställda ett virusinficerat e-postmeddelande till en klient. Som ett resultat blev data på klientens dator krypterade. Men den anställde svär att han inte skickade något. I samband med utredningen av incidenten begär säkerhetstjänsten vid företaget loggar från e-postservern för den 20 september, relaterade till den användare som utredningen gäller. Tack vare tidsstämpeln hittar systemadministratören den nödvändiga loggfilen, extraherar den information som behövs och överlämnar den till säkerhetstjänsten. Dessa granskar den och upptäcker att IP-adressen från vilken detta e-postmeddelande skickades motsvarar IP-adress användarens dator. Inspelningar från övervakningskameror bekräftade att den anställde befann sig på sin arbetsplats när han skickade e-postmeddelandet. Denna information räckte för att anklaga honom för att ha brutit mot reglerna för informationssäkerhet och avskeda honom. 

Exempel på att extrahera poster för ett av användarkontona från loggen Mailbox.log till en separat fil

Det blir betydligt mer komplicerat när det handlar om en flerserverinfrastruktur. Eftersom loggarna samlas lokalt är det mycket opraktiskt att hantera dem i en miljö med flera servrar, vilket motiverar behovet av centralisering av logginsamling. Detta kan göras genom att konfigurera en värd för logginsamling. Det finns ingen särskild anledning att lägga till en dedikerad värd i infrastrukturen. Vilken e-postserver som helst kan fungera som logginsamlingsnod. I vårt fall kommer detta att vara noden Mailstore01.

På denna server måste vi ange de kommandon som anges nedan:

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

Redigera filen /etc/sysconfig/rsyslog och ställ in parametern SYSLOGD_OPTIONS="-r -c 2"

Redigera /etc/rsyslog.conf och avkommentera följande rader:
$ModLoad imudp
$UDPServerRun 514

Skriv följande kommandon:

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

Kontrollera att allt fungerar med kommandot zmprov gacf | grep zimbraLogHostname. Efter körning av kommandot ska värdnamnet som samlar loggar visas. För att ändra detta, skriv kommandot zmprov mcf zimbraLogHostname mailstore01.company.ru.

På alla andra servrar i infrastrukturen (LDAP, MTA och andra e-postlagringstjänster) kör kommandot zmprov gacf | grep zimbraLogHostname för att se namnet på värden som tar emot loggar. För att ändra detta kan du också skriva kommandot zmprov mcf zimbraLogHostname mailstore01.company.ru.

Även på varje server behöver du skriva följande kommandon:

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

efter detta kommer alla loggar att registreras på den server som du angav, där de enkelt kan ses. Dessutom kommer den aktiva Logger-tjänsten att visas endast på servern mailstore01 i Zimbra OSE-administratörskonsolen på sidan med serverstatus.

En annan huvudvärk för administratörer kan vara att spåra ett visst e-postmeddelande. Eftersom e-post i Zimbra OSE går igenom flera olika händelser: antiviruskontroll, skräppostkontroll och så vidare, innan det accepteras eller skickas, kan det för administratören vara problematiskt att följa upp var meddelandet försvann om det inte kommer fram.

För att lösa detta problem kan man använda ett specialskript, som har utvecklats av informationssäkerhetsspecialisten Viktor Dukhonov och rekommenderas för användning av utvecklare av Postfix. Detta skript konkatenerar register från loggarna för en specifik process, vilket snabbt gör det möjligt att visa alla poster relaterade till sändningen av ett specifikt mejl baserat på dess identifierare. Det har testats på alla versioner av Zimbra OSE, från och med 8.7. Här är skriptets text.

#! /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";
}

Skriptet är skrivet i Perl och för att köra det måste du spara det i en fil collate.pl, göra det exekverbart och sedan köra filen med angivande av loggfilen och använda pgrep för att extrahera identifieringsinformationen för det sökta mejlet collate.pl /var/log/zimbra.log | pgrep ''. Resultatet blir en sekventiell utskrift av rader som innehåller information om mejlets rörelse på servern.

# 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

För alla frågor relaterade till Zextras Suite kan ni kontakta företagets representant "Zextras", Ekaterina Triandafiliidi, via e-post katerina@zextras.com

Källa: habr.com