pvemailforward loses emails if mail server is not available

[LaXiS]

Hello,

I am using Proxmox VE 7.1-12 on my main workstation which I start and shutdown daily.
I have configured postfix to forward local email to a smarthost as explained in this tutorial and confirmed that it does work, but I noticed that I never get the email after boot.

This is the syslog during all recent boots:

May 02 18:55:18 pc-pve postfix/pickup[1442]: 9A8D14C0FC3: uid=0 from=<root>
May 02 18:55:18 pc-pve postfix/cleanup[1445]: 9A8D14C0FC3: message-id=<20220502165518.9A8D14C0FC3@pc-pve.lan>
May 02 18:55:18 pc-pve postfix/qmgr[1443]: 9A8D14C0FC3: from=<root@pc-pve.lan>, size=1001, nrcpt=1 (queue active)
[...]
May 02 18:55:18 pc-pve pvemailforward[1448]: mail forward failed: Connection refused
May 02 18:55:18 pc-pve postfix/local[1447]: 9A8D14C0FC3: to=<root@pc-pve.lan>, orig_to=<root>, relay=local, delay=0.62, delays=0.44/0.01/0/0.17, dsn=2.0.0, status=sent (delivered to command: /usr/bin/pvemailforward)
May 02 18:55:18 pc-pve postfix/qmgr[1443]: 9A8D14C0FC3: removed

This is the syslog after running echo "test" | pvemailforward via shell:

May 02 20:36:25 pc-pve pvemailforward[19296]: forward mail to <redacted@mail.com>
May 02 20:36:25 pc-pve postfix/pickup[19117]: B96F84C1002: uid=0 from=<root>
May 02 20:36:25 pc-pve postfix/cleanup[19299]: B96F84C1002: message-id=<20220502183625.B96F84C1002@pc-pve.lan>
May 02 20:36:25 pc-pve postfix/qmgr[1443]: B96F84C1002: from=<root@pc-pve.lan>, size=244, nrcpt=1 (queue active)
May 02 20:36:26 pc-pve postfix/smtp[19301]: B96F84C1002: to=<redacted@mail.com>, relay=smtp-relay.sendinblue.com[185.107.232.248]:587, delay=0.46, delays=0.01/0.01/0.31/0.14, dsn=2.0.0, status=sent (250 Message queued as <20220502183625.B96F84C1002@pc-pve.lan>)
May 02 20:36:26 pc-pve postfix/qmgr[1443]: B96F84C1002: removed

The internet connection is always available and the SMTP smarthost is indeed up, but for some reason I always get Connection refused.
But that's not the main problem: I inspected the source for pvemailforward and it's clear that the script only ever returns success, therefore postfix always considers the message as successfully sent and removes it from the queue, without the message ever actually getting sent.
Why not just return an error value and let the postfix queue handle any successive retry?

Running mail as root in a shell yields No mail for root, so those messages are effectively lost.

Thanks

 

[Stoiko Ivanov]

his is the syslog during all recent boots:

May 02 18:55:18 pc-pve postfix/pickup[1442]: 9A8D14C0FC3: uid=0 from=<root>
May 02 18:55:18 pc-pve postfix/cleanup[1445]: 9A8D14C0FC3: message-id=<20220502165518.9A8D14C0FC3@pc-pve.lan>
May 02 18:55:18 pc-pve postfix/qmgr[1443]: 9A8D14C0FC3: from=<root@pc-pve.lan>, size=1001, nrcpt=1 (queue active)
[...]
May 02 18:55:18 pc-pve pvemailforward[1448]: mail forward failed: Connection refused
May 02 18:55:18 pc-pve postfix/local[1447]: 9A8D14C0FC3: to=<root@pc-pve.lan>, orig_to=<root>, relay=local, delay=0.62, delays=0.44/0.01/0/0.17, dsn=2.0.0, status=sent (delivered to command: /usr/bin/pvemailforward)
May 02 18:55:18 pc-pve postfix/qmgr[1443]: 9A8D14C0FC3: removed

what's in the logs afterwards? (pvemailforward should create a new mail and send it via postfix...)

 

[LaXiS]

what's in the logs afterwards? (pvemailforward should create a new mail and send it via postfix...)

There aren't any additional logs coming from either postfix or pvemailforward, even after the machine has been up for some hours.
I can attach a full log but only later tonight.

 

[Stoiko Ivanov]

May 02 18:55:18 pc-pve pvemailforward[1448]: mail forward failed: Connection refused

sorry - I missed this logline - this should be a good pointer already
pvemailforwards calls sendmail with appropriate options

what and where is the sendmail binary on your system?
* `which sendmail`
* `ls -la $(which sendmail)
* `dpkg -S $(which sendmail)`

 

[LaXiS]

sorry - I missed this logline - this should be a good pointer already
pvemailforwards calls sendmail with appropriate options

what and where is the sendmail binary on your system?
* `which sendmail`
* `ls -la $(which sendmail)
* `dpkg -S $(which sendmail)`

Thank you, the installation is a clean one from the latest 7.1 ISO, updated with no-subscription packages and with very little changes to the base OS.
Here you go:

root@pc-pve:~# which sendmail
/usr/sbin/sendmail
root@pc-pve:~# ls -la $(which sendmail)
-rwxr-xr-x 1 root root 30872 May  4  2021 /usr/sbin/sendmail
root@pc-pve:~# dpkg -S $(which sendmail)
postfix: /usr/sbin/sendmail

 

[Stoiko Ivanov]

hm - is postfix listening on port 25?

just in case - try running `dpkg-reconfigure postfix` and go through the dialog there

 

[LaXiS]

hm - is postfix listening on port 25?

just in case - try running `dpkg-reconfigure postfix` and go through the dialog there

Yes, postfix is listening as expected:

root@pc-pve:~# ss -tulnp | grep :25
tcp   LISTEN 0      100        127.0.0.1:25        0.0.0.0:*    users:(("master",pid=1444,fd=13))                                                                                                      
tcp   LISTEN 0      100            [::1]:25           [::]:*    users:(("master",pid=1444,fd=14))

I ran dpkg-reconfigure postfix and configured it like other Debian installations I already have working, will see if this fixes it.

Thank you

 

[LaXiS]

Quick update: for some reason, since reconfiguring postfix I have yet to receive any automated email or even get the error logs that I was seeing earlier.
I guess we'll never know what those lost emails had to say

 

[Elliott Partridge]

I've run into this issue as well, trying to send an email at startup & shutdown. pvemailforward fails with the same "Connection refused", even though the mail server is up. This occurs during system boot-up; it's picking up an email sent when the server shutdown (need to figure out how to send mail prior to postfix shutting down - that's a separate issue).

Why isn't pvemailforward or postfix retrying later?

My similar-looking log:

Sep 01 14:50:45 pve1 postfix/pickup[1249]: ED66C499: uid=0 from=<root@pve1.domain.lan>
Sep 01 14:50:45 pve1 postfix/cleanup[1252]: ED66C499: message-id=<20220901185045.ED66C499@pve1.domain.lan>
Sep 01 14:50:46 pve1 postfix/qmgr[1250]: ED66C499: from=<root@pve1.domain.lan>, size=445, nrcpt=1 (queue active)
Sep 01 14:50:46 pve1 pvemailforward[1255]: mail forward failed: Connection refused
Sep 01 14:50:46 pve1 postfix/local[1254]: ED66C499: to=<root@pve1.domain.lan>, relay=local, delay=135, delays=135/0.02/0/0.59, dsn=2.0.0, status=sent >
Sep 01 14:50:46 pve1 postfix/qmgr[1250]: ED66C499: removed

 

[Stoiko Ivanov]

Why isn't pvemailforward or postfix retrying later?

pvemailforward is just a small executable, that reads the user.cfg (and datacenter.cfg for the sender) and then sends the mail using /usr/sbin/sendmail - there is no queueing logic integrated there.

with a bit more of the log we might get an idea where the issue is rooted - my current guess is that the clusterfilesystem is not setup yet thus the user.cfg and datacenter.cfg cannot be read...

 

[Elliott Partridge]

Interesting. So you're saying that if the cluster file system is not available when postfix is started, pvemailforward doesn't know where to forward the mail? That makes sense to me. Can this be fixed simply by returning an error code to postfix?

I've attached the boot log from the journal. Note that there are two mails attempted - one from the previous shutdown, and another as a part of startup. The first one fails, the second is deferred. See timestamps 14:50:45 and 14:52:50.

The corresponding /var/log/mail.log from the sending server:

Sep  1 14:50:45 pve1 postfix/postfix-script[1246]: starting the Postfix mail system
Sep  1 14:50:45 pve1 postfix/master[1248]: daemon started -- version 3.5.13, configuration /etc/postfix
Sep  1 14:50:45 pve1 postfix/pickup[1249]: ED66C499: uid=0 from=<root@pve1.domain.lan>
Sep  1 14:50:45 pve1 postfix/cleanup[1252]: ED66C499: message-id=<20220901185045.ED66C499@pve1.domain.lan>
Sep  1 14:50:46 pve1 postfix/qmgr[1250]: ED66C499: from=<root@pve1.domain.lan>, size=445, nrcpt=1 (queue active)
Sep  1 14:50:46 pve1 postfix/local[1254]: ED66C499: to=<root@pve1.domain.lan>, relay=local, delay=135, delays=135/0.02/0/0.59, dsn=2.0.0, status=sent (delivered to command: /usr/bin/pvemailforward)
Sep  1 14:50:46 pve1 postfix/qmgr[1250]: ED66C499: removed
Sep  1 14:52:49 pve1 postfix/pickup[1249]: 7D11E1F71: uid=0 from=<root@pve1.domain.lan>
Sep  1 14:52:49 pve1 postfix/cleanup[9091]: 7D11E1F71: message-id=<20220901185249.7D11E1F71@pve1.domain.lan>
Sep  1 14:52:49 pve1 postfix/qmgr[1250]: 7D11E1F71: from=<root@pve1.domain.lan>, size=399, nrcpt=1 (queue active)
Sep  1 14:52:50 pve1 postfix/pickup[1249]: 0F9111F77: uid=65534 from=<pve@domain.com>
Sep  1 14:52:50 pve1 postfix/cleanup[9091]: 0F9111F77: message-id=<20220901185249.7D11E1F71@pve1.domain.lan>
Sep  1 14:52:50 pve1 postfix/local[9115]: 7D11E1F71: to=<root@pve1.domain.lan>, relay=local, delay=0.58, delays=0.04/0.01/0/0.53, dsn=2.0.0, status=sent (delivered to command: /usr/bin/pvemailforward)
Sep  1 14:52:50 pve1 postfix/qmgr[1250]: 7D11E1F71: removed
Sep  1 14:52:50 pve1 postfix/qmgr[1250]: 0F9111F77: from=<pve@domain.com>, size=597, nrcpt=1 (queue active)
Sep  1 14:52:53 pve1 postfix/smtp[9388]: connect to mail.domain.lan[192.168.x.12]:25: No route to host
Sep  1 14:52:53 pve1 postfix/smtp[9388]: 0F9111F77: to=<forwardaddress@domain.com>, relay=none, delay=3.2, delays=0.03/0.15/3.1/0, dsn=4.4.1, status=deferred (connect to mail.domain.lan[192.168.x.12]:25: No route to host)
Sep  1 15:00:45 pve1 postfix/qmgr[1250]: 0F9111F77: from=<pve@domain.com>, size=597, nrcpt=1 (queue active)
Sep  1 15:00:46 pve1 postfix/smtp[60955]: 0F9111F77: to=<forwardaddress@domain.com>, relay=mail.domain.lan[192.168.x.12]:25, delay=476, delays=476/0.02/0.22/0.23, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D12ED8110)
Sep  1 15:00:46 pve1 postfix/qmgr[1250]: 0F9111F77: removed

The mail.log from the mail relay (also postfix). This only shows one email being sent at 15:00:45:

Sep  1 15:00:45 mail1 postfix/smtpd[310]: connect from pve1.domain.lan[192.168.x.30]
Sep  1 15:00:45 mail1 postfix/smtpd[310]: D12ED8110: client=pve1.domain.lan[192.168.x.30]
Sep  1 15:00:45 mail1 postfix/cleanup[315]: D12ED8110: message-id=<20220901185249.7D11E1F71@pve1.domain.lan>
Sep  1 15:00:46 mail1 postfix/qmgr[308]: D12ED8110: from=<pve@domain.com>, size=846, nrcpt=1 (queue active)
Sep  1 15:00:46 mail1 postfix/smtpd[310]: disconnect from pve1.domain.lan[192.168.x.30] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Sep  1 15:00:46 mail1 postfix/smtp[316]: connect to localhost[::1]:2525: Connection refused
Sep  1 15:00:46 mail1 postfix/smtp[316]: D12ED8110: replace: header From: root <root@pve1.domain.lan>: From: pve1@domain.com
Sep  1 15:00:46 mail1 postfix/smtp[316]: D12ED8110: to=<forwardaddress@domain.com>, relay=localhost[127.0.0.1]:2525, delay=0.72, delays=0.22/0/0.2/0.3, dsn=2.0.0, status=sent (250 Ok 01000182fa6d58aa-da74ffdf-5ed7-4878-a57f-bec2efbfc2ff-000000)
Sep  1 15:00:46 mail1 postfix/qmgr[308]: D12ED8110: removed

 

[Stoiko Ivanov]

Thanks for the logs - as expected (and then reproduced locally) - the mail was lost since pmxcfs was not running (it started a few seconds after postfix) - thus pvemailforward could not look up the destination address.

Not sure how to address this in a clean way (or whether this is something that happens too often) - but I'll try to come up with a patch

Thanks for the report in any case!

 

[Elliott Partridge]

Thanks for the logs - as expected (and then reproduced locally) - the mail was lost since pmxcfs was not running (it started a few seconds after postfix) - thus pvemailforward could not look up the destination address.

Not sure how to address this in a clean way (or whether this is something that happens too often) - but I'll try to come up with a patch

Thanks for the report in any case!

Glad you were able to reproduce! I'm going to piggy back off this discussion in another thread to answer my other question about how to configure a systemd service to guarantee mail delivery during startup/shutdown (as far as the system dependencies are concerned).

 

[Stoiko Ivanov]

just for completeness sake - the initial patch (although I currently think that the solution is not optimal):
https://lists.proxmox.com/pipermail/pve-devel/2022-September/053837.html