Debug Fortianalyzer mail notifications sending

Mon 13 January 2025 in Fortinet

#Fortigate #Fortianalyzer

Table of Contents

Sending test mail from FAZ
Enable real-time debug
- Restart fazmaild mail daemon on FAZ
Sending mails via default Frotinet servers

Sending test mail from FAZ

FAZ has a command to actually send a test mail that checks if sending mails to/via the configured mail server works. It does NOT check whether mail notification is fired in FAZ as should. The command asks for the mail server object name as configured under config sys mail in FAZ, any other form will fail.

diagnose test connection mailserver mx.example.yurisk.info faz@example.yurisk.info root@example.yurisk.info

Where:

faz@example.yurisk.info is From: field.
root@example.yurisk.info is To: field.

The output when all works looks:

diagnose test connection mailserver mx.example.yurisk.info  faz@example.yurisk.info
                                                        root@example.yurisk.info  ↩
Testing SMTP server mx.example.yurisk.info, please wait...
* Host mx.example.yurisk.info:25 was resolved.
* IPv6: (none)
* IPv4: 10.100.104.15
*   Trying 10.100.104.15:25...
* Connected to mx.example.yurisk.info (10.100.104.15) port 25
< 220 mx.example.yurisk.info ESMTP Postfix
> EHLO FAZ-AWS
< 250-mx.example.yurisk.info
< 250-PIPELINING
< 250-SIZE 10240000
< 250-VRFY
< 250-ETRN
< 250-ENHANCEDSTATUSCODES
< 250-8BITMIME
< 250 DSN
> MAIL FROM:<faz@example.yurisk.info>
< 250 2.1.0 Ok
> RCPT TO:<root@example.yurisk.info>
< 250 2.1.5 Ok
> DATA
< 354 End data with <CR><LF>.<CR><LF>
< 250 2.0.0 Ok: queued as EEDA4492D
* Connection #0 to host mx.example.yurisk.info left intact
A test email has been sent to root@example.yurisk.info through mx.example.yurisk.info.

And this test email indeed appears in the inbox on the mail server.

All the rules of correct SMTP transactions apply - below, for example, I specified non-existing mail box in To: field:

# diagnose test connection mailserver mx.example.yurisk.info
    root@example.yurisk.info  fgt@example.yurisk.info  ↩
Testing SMTP server mx.example.yurisk.info, please wait...
* Host mx.example.yurisk.info:25 was resolved.
* IPv6: (none)
* IPv4: 10.100.104.15
*   Trying 10.100.104.15:25...
* Connected to mx.example.yurisk.info (10.100.104.15) port 25
< 220 mx.example.yurisk.info ESMTP Postfix
> EHLO FAZ-AWS
< 250-mx.example.yurisk.info
< 250-PIPELINING
< 250-SIZE 10240000
< 250-VRFY
< 250-ETRN
< 250-ENHANCEDSTATUSCODES
< 250-8BITMIME
< 250 DSN
> MAIL FROM:<faz@example.yurisk.info>
< 250 2.1.0 Ok
> RCPT TO:<fgt@example.yurisk.info>
< 550 5.1.1 <fgt@example.yurisk.info>: Recipient address rejected: User unknown in local recipient table
* RCPT failed: 550
> QUIT
< 221 2.0.0 Bye
* Closing connection
Failed to send a test email to fgt@example.yurisk.info through mx.example.yurisk.info.
Please check your configuration.
Command fail. Return code 55

If you enable Authentication in the config sys mail settings, the sending can fail for wrong password/user, when using SMTPS/TLS as transport protocol, the sending may fail for expired TLS certificates etc. All these reasons will be listed in the test result.

Enable real-time debug

Helpful when debugging issues in real-time and mails are not being sent. It is good to start with basics: ping, if the mail server answers pings:

exe ping mx.example.yurisk.info Also checking on the way DNS resolving.

Show queue status:

diagnose test application fazmaild 2

total sent mail count:       0
total failed sendmail count: 0
total discard mail count:    0
last sendmail time:          Mon Jan 13 17:31:16 2025
last request time:           Mon Jan 13 17:31:18 2025
queue:                       0/5000
queue timeout:               1800 seconds

Enable real-time debug:

diagnose debug application fazmaild 255 (Note: in FAZ 7.6 it is 8 instead of 255)

diagnose debug timestamp enable

dia deb enable

Example of FAZ trying to send mail but the configured mail server is not responding/not reachable:

2025-01-13 17:38:25 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782659, last sendmail time 1736782663
2025-01-13 17:38:45 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782659, last sendmail time 1736782663
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:1146] total pending tasks: 3.
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:1154] sending mail: 1be44265-3b00-dc48-acf2-02a4b13bdc1c

Here fires the Incident Handler on Fortigate configuration changed by administrator (new admin user being created in the FGT), FAZ composes the email with log in it to root@example.yurisk.info:

2025-01-13 17:39:03 [T30241:faz_mail_worker.c:469] mail server mx.example.yurisk.info has not been marked as unreachable
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:500] got mail by name mx.example.yurisk.info
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:151] To: root@example.yurisk.info
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:157] From: faz@example.yurisk.info
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:163] Subject: Alert from FAZ (medium system alert devname-vdom:FGT-Perimeter/root FGT-Perimeter)
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:172] Date: Mon, 13 Jan 2025 17:39:03 +0200(IST)
2025-01-13 17:39:03 [T30241:faz_mail_worker.c:196] MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="mixed_fazmaild_v1_1736782743"
Content-Type: text/plain; charset="utf-8"; format=flowed
Content-Transfer-Encoding: 7bit

Subject: devname-vdom:FGT-Perimeter/root
Device: FGT-Perimeter
Severity: medium
From: FAZ-AWS(FAZAWSTA23002441)
Trigger: Fortigate configuration changed by administrator with details
alertid: 202501131000160015
Log message:
logver=0704062726 idseq=146193085871685637 itime=1736782636 devid="FGTAWSN1JDGCU42E" devname="FGT-Perimeter"
vd="root" date=2025-01-13 time=07:37:16 eventtime=1736782635188155248 tz="-0800" logid="0100044547" type="event"
subtype="system" level="information" logdesc="Object attribute configured" user="yuri_admin" ui="GUI(146.70.182.36)"
action="Add" cfgtid=130875396 cfgpath="system.admin" cfgobj="deleteme33"
cfgattr="accprofile[super_admin_readonly]vdom[root]password[*]" msg="Add system.admin deleteme33"


2025-01-13 17:39:03 [T30241:faz_mail_worker.c:207]

Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 7bit

Body of the mail message (of no interest to us):

2025-01-13 17:39:03 [T30241:faz_mail_worker.c:232] <html><head><meta http-equiv="content-type" content="text/html; charset=utf-8" /></head><body><table border="0" cellspacing="0" cellpadding="2"><tbody> <tr><td width="120">Device</td><td>FGT-Perimeter</td></tr> <tr><td width="120">Severity</td><td>medium</td></tr> <tr><td width="120">From</td><td>FAZ-AWS(FAZAWSTA23002441)</td></tr> <tr><td width="120">Trigger</td><td>Fortigate configuration changed by administrator with details</td></tr> <tr><td width="120">Tag</td><td></td></tr> <tr><td width="120">Alertid</td><td>202501131000160015</td></tr></tbody></table> <br/><div>Log Details: <table border="1" cellpadding="2" cellspacing="0"><tbody> <tr bgcolor="#EDF5FF"><td width="20%">logver</td><td width="30%"><pre>0704062726</pre></td><td width="20%">idseq</td><td width="30%"><pre>146193085871685637</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Time Stamp</td><td width="30%">2025-01-13 17:37:16</td><td width="20%">Device ID</td><td width="30%"><pre>FGTAWSN1JDGCU42E</pre></td></tr> <tr bgcolor="#EDF5FF"><td width="20%">Device Name</td><td width="30%"><pre>FGT-Perimeter</pre></td><td width="20%">Virtual Domain</td><td width="30%"><pre>root</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Date</td><td width="30%"><pre>2025-01-13</pre></td><td width="20%">Time</td><td width="30%"><pre>07:37:16</pre></td></tr> <tr bgcolor="#EDF5FF"><td width="20%">eventtime</td><td width="30%"><pre>1736782635188155248</pre></td><td width="20%">Time Zone</td><td width="30%"><pre>-0800</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Log ID</td><td width="30%"><pre>0100044547</pre></td><td width="20%">Type</td><td width="30%"><pre>event</pre></td></tr> <tr bgcolor="#EDF5FF"><td width="20%">Sub Type</td><td width="30%"><pre>system</pre></td><td width="20%">Level</td><td width="30%"><pre>information</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Log Description</td><td width="30%"><pre>Object attribute configured</pre></td><td width="20%">User</td><td width="30%"><pre>yuri_admin</pre></td></tr> <tr bgcolor="#EDF5FF"><td width="20%">User Interface</td><td width="30%"><pre>GUI(146.70.182.36)</pre></td><td width="20%">Action</td><td width="30%"><pre>Add</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Config Transaction ID</td><td width="30%"><pre>130875396</pre></td><td width="20%">Config Path</td><td width="30%"><pre>system.admin</pre></td></tr> <tr bgcolor="#EDF5FF"><td width="20%">Config Object</td><td width="30%"><pre>deleteme33</pre></td><td width="20%">Config Attributes</td><td width="30%"><pre>accprofile[super_admin_readonly]vdom[root]password[*]</pre></td></tr> <tr bgcolor="#FFFFFF"><td width="20%">Message</td><td width="30%"><pre>Add system.admin deleteme33</pre></td><td></td><td></td></tr> </tbody></table></div></body></html>

And here happens the error in trying to reach the mail server:

2025-01-13 17:39:04 [T30241:faz_mail_worker.c:311] buffer size 9660, len 9, actual len 9
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:665] send mail <Alert from FAZ
(medium system alert devname-vdom:FGT-Perimeter/root FGT-Perimeter)> failed: 7: Couldn't connect to server. <-- ERROR

next, FAZ marks this mail server as unreachble:

2025-01-13 17:39:07 [T30241:faz_mail_worker.c:864] /drive0/private/fazmaild/tasks/1be44265-3b00-dc48-acf2-02a4b13bdc1c/mdata.js create time 1736782743, now 1736782747
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:1154] sending mail: 85c372ee-1748-2243-9386-8be2b3a669a6
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:464] mail skipped mx.example.yurisk.info
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:658] Create mail info failed.
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:864] /drive0/private/fazmaild/tasks/85c372ee-1748-2243-9386-8be2b3a669a6/mdata.js create time 1736782747, now 1736782747
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:1154] sending mail: ff983ac3-f218-ad45-ac89-1b8c797e2d3a
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:464] mail skipped mx.example.yurisk.info
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:658] Create mail info failed.
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:864] /drive0/private/fazmaild/tasks/ff983ac3-f218-ad45-ac89-1b8c797e2d3a/mdata.js create time 1736782747, now 1736782747
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:913] Success count 0
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:915] Error count   0
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:917] Failed count  0
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:919] Removed count 0
2025-01-13 17:39:07 [T30241:faz_mail_worker.c:921] Discard count 0

Next, FAZ starts counting trials to reach it:

2025-01-13 17:39:07 [T30241:faz_mail_worker.c:935] Unreachable server mx.example.yurisk.info, count 3

FAZ will try and send mail with increasing intervals:

2025-01-13 17:39:09 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:39:29 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:39:49 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:40:09 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:40:29 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:40:49 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:41:09 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:41:29 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:41:49 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736782743, last sendmail time 1736782747 2025-01-13 17:42:07 [T30241:faz_mail_worker.c:1146] total pending tasks: 3.

To see if FAZ is actually trying to reach the mail server we can do packet sniffer on FAZ (here 10.100.104.15 is mail server):

dia sni pa any 'host 10.100.104.15' 3 FAZ only allows setting verbosity to 3 as max, no 6 is present.

FAZ-AWS # dia sni pa any 'host 10.100.104.15' 3
interfaces=[any]
filters=[host 10.100.104.15]
63.467049 arp who-has 10.100.104.15 tell 10.100.104.17
0x0000   0000 0000 0000 0aa6 0d24 11df 0806 0001        .........$......
0x0010   0800 0604 0001 0aa6 0d24 11df 0a64 6811        .........$...dh.
0x0020   0000 0000 0000 0a64 680f                       .......dh.

64.472019 arp who-has 10.100.104.15 tell 10.100.104.17
0x0000   0000 0000 0000 0aa6 0d24 11df 0806 0001        .........$......
0x0010   0800 0604 0001 0aa6 0d24 11df 0a64 6811        .........$...dh.
0x0020   0000 0000 0000 0a64 680f                       .......

We can see in the above that FAZ is trying to resolve via ARP the mac address of the mail server and gets no answer, so not even trying to initiate TCP to port 25.

The moment I bring up the mail server, FAZ 2-3 minutes later resumes trying to connect to port 25 this time successfully:

# dia sni pa any 'host 10.100.104.15 and port 25' 3
interfaces=[any]
filters=[host 10.100.104.15 and port 25]
141.329120 10.100.104.17.53534 -> 10.100.104.15.25: syn 909952265
0x0000   0000 0000 0000 0aa6 0d24 11df 0800 4500        .........$....E.
0x0010   0034 9a02 4000 4006 bbd9 0a64 6811 0a64        .4..@.@....dh..d
0x0020   680f d11e 0019 363c c509 0000 0000 8002        h.....6<........
0x0030   faf0 e50e 0000 0204 05b4 0101 0402 0103        ................
0x0040   030a                                           ..

141.329274 10.100.104.15.25 -> 10.100.104.17.53534: syn 3093655189 ack 909952266
0x0000   0000 0000 0001 0a87 3504 a5c5 0800 4500        ........5.....E.
0x0010   0034 0000 4000 ff06 96db 0a64 680f 0a64        .4..@......dh..d
0x0020   6811 0019 d11e b865 6e95 363c c50a 8012        h......en.6<....
0x0030   6903 104f 0000 0204 2301 0101 0402 0103        i..O....#.......
0x0040   0307                                           ..

141.329293 10.100.104.17.53534 -> 10.100.104.15.25: ack 3093655190
0x0000   0000 0000 0000 0aa6 0d24 11df 0800 4500        .........$....E.
0x0010   0028 9a03 4000 4006 bbe4 0a64 6811 0a64        .(..@.@....dh..d
0x0020   680f d11e 0019 363c c50a b865 6e96 5010        h.....6<...en.P.
0x0030   003f e502 0000                                 .?....

141.354917 10.100.104.15.25 -> 10.100.104.17.53534: psh 3093655190 ack 909952266
0x0000   0000 0000 0001 0a87 3504 a5c5 0800 4500        ........5.....E.
0x0010   0052 da09 4000 ff06 bcb3 0a64 680f 0a64        .R..@......dh..d
0x0020   6811 0019 d11e b865 6e96 363c c50a 5018        h......en.6<..P.
0x0030   00d3 fb0a 0000 3232 3020 6d78 2e65 7861        ......220.mx.exa
0x0040   6d70 6c65 2e79 7572 6973 6b2e 696e 666f        mple.yurisk.info
0x0050   2045 534d 5450 2050 6f73 7466 6978 0d0a        .ESMTP.Postfix..

In FAZ mail debug, it just switches from no pending request to sending mail:

2025-01-13 18:07:02 [T30241:faz_mail_worker.c:935] Unreachable server mx.example.yurisk.info, count 3
2025-01-13 18:07:04 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:07:24 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:07:44 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:08:04 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:08:24 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:08:44 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:09:04 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:09:25 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:09:45 [T30241:faz_mail_worker.c:1129] no pending email request, last request time 1736784232, last sendmail time 1736784422
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:1146] total pending tasks: 3.
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:1154] sending mail: 1ec1e8f1-29e9-ff41-b9f1-c0805760bce1
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:469] mail server mx.example.yurisk.info has not been marked as unreachable
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:500] got mail by name mx.example.yurisk.info
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:151] To: root@example.yurisk.info
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:157] From: faz@example.yurisk.info
2025-01-13 18:10:03 [T30241:faz_mail_worker.c:163] Subject: Alert from FAZ (high system alert devname:FGT-Perimeter FGT-Perimeter)
==CUT==

If I keep mail server up, but Postfix is down - FAZ keeps trying to establish TCP to port 25, no other checks are done, until I bring up Postfiz on mail server and then FAZ sends waiting mails.

Here the server is up but Postfix service is down:

2025-01-13 18:18:11 [T30241:faz_mail_worker.c:311] buffer size 9603, len 9, actual len 9
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:665] send mail <Alert from FAZ (high system alert devname:FGT-Perimeter FGT-Perimeter)
> failed: 7: Couldn't connect to server.

2025-01-13 18:18:11 [T30241:faz_mail_worker.c:864] /drive0/private/fazmaild/tasks/7626c8e6-7ee9-994a-b9ad-01649b34eca2/mdata.js
 create time 1736785090, now 1736785091
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:913] Success count 0
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:915] Error count   0
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:917] Failed count  0
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:919] Removed count 0
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:921] Discard count 0
2025-01-13 18:18:11 [T30241:faz_mail_worker.c:935] Unreachable server mx.example.yurisk.info, count 1

Restart fazmaild mail daemon on FAZ

We can restart the process responsible for sending mails in FAZ with:

diagnose test application fazmaild 99

Sending mails via default Frotinet servers

We can use Fortinet mail servers if we don’t have our own, be advised though, that this is a "best effort" service and mails can be/seen being delayed for various reasons. But if options are this or nothing…

To use Fortinet Notification mail servers, set under config sys mail the following parameters:

set auth enable
set auth-type certificate
set port 465
set server "notification.fortinet.net"
See also Fortianalyzer diagnose and debug cheat sheet

I also write cheat sheets/scripts/guides to help in daily work, so make sure to check out my Github at https://github.com/yuriskinfo