How to work with Zimbra OSE logs
All local logs are stored by Zimbra OSE in the / opt / zimbra / log folder; logs can also be found in the /var/log/zimbra.log file. The most important of these is mailbox.log. It records all the actions that take place on the mail server. Among them are the transmission of letters, data on user authentication, unsuccessful login attempts, and others. The entries in mailbox.log are a text string that contains the time at which the event occurred, the level of the event, the number of the stream within which the event occurred, the username and his ip-address, as well as the text description of the event.
The log level indicates the degree to which the event affects the server. By default, 4 levels of events are used: INFO, WARN, ERROR and FATAL. Let’s analyze all the levels in order of increasing severity.
- INFO – Events at this level are usually designed to inform about the progress of the Zimbra OSE. Messages of this level include reports on creating or deleting a mailbox, and so on.
- WARN – events of this level inform about situations that are potentially dangerous, but do not affect the operation of the server. The WARN level, for example, marks a message about a failed user login attempt.
- ERROR – this level of event in the log informs about an error that is local in nature and does not interfere with the operation of the server. This level can be used to flag an error in which the index data of an individual user is corrupted.
- FATAL – This level marks errors due to which the server cannot continue to operate normally. For example, the FATAL level will be in the record about the impossibility to connect to the DBMS.
The mail server log file is updated every day. The latest version of the file is always named Mailbox.log, while the logs for a certain date have a date in their name and are contained in the archive. For example mailbox.log.2020-09-29.tar.gz. This greatly simplifies backing up action logs and searching through logs.
For the convenience of the system administrator, the / opt / zimbra / log / folder contains other logs. They include only those entries that relate to specific Zimbra OSE elements. For example, audit.log contains only entries about user authentication, clamd.log contains data about antivirus operation, and so on. By the way, an excellent method to protect the Zimbra OSE server from intruders is to protect the server using Fail2Ban, which just works based on audit.log. It is also good practice to add a cron task to execute the command grep -ir “invalid password” /opt/zimbra/log/audit.logto receive daily login information about unsuccessful login attempts.
An example of how twice incorrectly entered password and successful login attempt are displayed in audit.log
Logs in Zimbra OSE can be extremely useful in determining the causes of various critical failures. At the moment when a critical error occurs, the administrator usually has no time to read the logs. It is required to restore the server operation as soon as possible. However, later, when the server is running again and generates many logs, it can be difficult to find the required entry in a large file. In order to quickly find an error record, it is enough to know the time at which the server was restarted and to find an entry in the logs dated by this time. The previous record will be the record of the error that occurred. You can also find the error message by searching for the FATAL keyword.
Also, the Zimbra OSE logs allow you to identify non-critical failures. For example, to find handler exceptions, you can search for handler exception. Often, errors generated by handlers are accompanied by a stack trace, which explains what caused the exception. In case of errors with mail delivery, you should start your search with the LmtpServer keyword, and to search for errors related to the POP or IMAP protocols, you can use the ImapServer and Pop3Server keywords.
Also, logs can help in the investigation of information security incidents. Let’s consider a specific example. On September 20, one of the employees sent a virus-infected letter to the client. As a result, the data on the client’s computer was encrypted. However, the employee swears that he did not send anything. As part of an incident investigation, the enterprise security service requests the system administrator for the September 20 mail server logs associated with the user under investigation. Thanks to the time stamp, the system administrator finds the necessary file with logs, extracts the necessary information and transfers it to security personnel. Those, in turn, look through it and find that the IP address from which this letter was sent matches the IP address of the user’s computer. CCTV footage confirmed that the employee was at his workplace when the letter was sent. This data was enough to accuse him of violating information security rules and dismiss him.
An example of extracting records about one of the accounts from the Mailbox.log into a separate file
Things get much more complicated when it comes to multi-server infrastructure. Since logs are collected locally, it is very inconvenient to work with them in a multi-server infrastructure and therefore there is a need to centralize the collection of logs. This can be done by configuring the host to collect logs. There is no particular need to add a dedicated host to the infrastructure. Any mail server can act as a node for collecting logs. In our case, this will be the Mailstore01 node.
On this server, we need to enter the following commands:
sudo su – zimbra
zmcontrol stop
exit
sudo /opt/zimbra/libexec/zmfixperms -e -vEdit the file / etc / sysconfig / rsyslog and set the SYSLOGD_OPTIONS = “- r -c 2” parameter
Edit /etc/rsyslog.conf and uncomment the following lines:
$ ModLoad imudp
$ UDPServerRun 514
Enter the following commands:
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/zmupdateauthkeysYou can check that everything is working with the command zmprov gacf | grep zimbraLogHostname. After executing the command, the name of the host that collects the logs should be displayed. In order to change it, you must enter the command zmprov mcf zimbraLogHostname mailstore01.company.ru.
On all other infrastructure servers (LDAP, MTA and other mail storages), run the command zmprov gacf | grep zimbraLogHostname to see the name of the host to which the logs go. To change it, you can also enter the command zmprov mcf zimbraLogHostname mailstore01.company.ru
Also, on each server, you must enter the following commands:
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 restartAfter that, all logs will be recorded on the server you specified, where they can be conveniently viewed. Also in the Zimbra OSE administrator console on the screen with information about the status of the servers, the running Logger service will be displayed only on the mailstore01 server.
Another headache for an administrator can be tracking a specific email message. Since emails in Zimbra OSE go through several different events at once: checking by antivirus, antispam, and so on, before being received or sent, for the administrator, if an email does not reach, it can be quite problematic to trace at what stage it was lost …
In order to solve this problem, you can use a special script that was developed by information security specialist Viktor Dukhovny and is recommended for use by Postfix developers. This script concatenates records from logs for a specific process and, due to this, allows you to quickly display all the records associated with sending a particular letter based on its identifier. Its work has been tested on all versions of Zimbra OSE, starting from 8.7. Here is the text of the script.
#! /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 "https://habr.com/"
(?:/S+)* # Optional non-captured "https://habr.com/"-delimited qualifiers
/ # Final "https://habr.com/" 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";
}The script is written in Perl and to run it you need to save it to a file collate.pl, make it executable, and then run the file specifying the log file and use pgrep to extract the identification information of the desired letter collate.pl /var/log/zimbra.log | pgrep ‘<20200929164500 .user @ mail .company .ru>‘… The result will be a sequential output of lines, which contain information about the movement of the letter on the server.
# 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: removedFor all questions related to Zextras Suite, you can contact the Representative of the Zextras company Ekaterina Triandafilidi by e-mail katerina@zextras.com
