dovecot-lmtp

[toml]

I am running into a problem, that I have not been able to figure out. I have a system that has been running pretty solidly for years. About 3 days ago, I noticed one of my logwatch emails didn't come through. After a couple of days I thought that there was an issue with cron but it looks to be a problem with dovecot-lmtp process.

I can see in the exim/mainlog that the email was delivered to dovecot_lmtp_udp, I can see in the dovecot-lmtp.log file that is received the email and according to the logs.
exim/mainlog:
2024-08-07 14:51:08 1sboYm-00000001Ehz-13br => tom <[email protected]> F=<bounce-mc.us7_148369750.5730651-191617c830@mail172.atl21.rsgsv.net> R=virtual_user T=dovecot_lmtp_udp S=74068 C="250 2.0.0 <[email protected]> eFYELUzss2asdgQA7JJOBg Saved"
dovecot-lmtp.log:
Aug 07 14:51:08 lmtp([email protected])<292524><eFYELUzss2asdgQA7JJOBg>: Info: sieve: msgid=<f6433ce6f921519a43d1ddddc.191617c830.20240807213131.bef28560b6.dd815295@mail172.atl21.rsgsv.net>: stored mail into mailbox 'INBOX'

In rspamd I see this:

f6433ce6f921519a43d1ddddc.191617c830.20240807213131.bef28560b6.dd815295@mail172.atl21.rsgsv.net

205.201.133.172

[bounce-mc.us7_148369750.5730651-191617c830@mail172.atl21.rsgsv.net] [email protected]

[email protected]

Visa/Mastercard Filing Deadline is Fast Approaching

no action

70.6 KiB

0.336

8/7/2024, 2:51:08 PM

unknown

[td]

7.03 / 15​

[/td]​

It appears as though the file was created in the user's INBOX directory, but the file never gets written to the Maildir. As you can see, there wasn't any action on rspamd to do anything with the email, and my personal spam filter didn't even see the email because it was never served via IMAP because it was never there. This is happening to a good percentage of emails to one of my virtual accounts, and from what I can see it isn't affecting any other accounts.

I don't see anything in any of the log files that relate to OOM or anything else that might affect the files being written. I even set up a forwarder to try and not lose any more emails but even those are not getting forwarded. It is almost like the process reading from the lmtp socket is crashing before it gets to write the email or log an error. Of course I don't see any evidence of that either, it is quite frustrating. I even setup some straces on a dovecot lmtp process but after sending 20 emails, it didn't seem to hit that processes, so I gave up that method of debugging.

I recently rebooted the server, rebuilt exim, dovecot, dovecot pigeonhole, exim_conf, dovecot_conf and the problem is still occurring. Any ideas on how to fix this without taking down my whole email system while clients are active?

 

[Stije]

So your Local mail is not working for all or just specifick mailadresses?

Do you have some Sieve filtering on?

Did you also check the spamassasin setup of the receiver?

Did you do a set_permission on your mail?

So either:

#for user specifick
./set_permissions.sh maildir <user> <path/Maildir>

#for all
./set_permissions.sh email

 

[toml]

So your Local mail is not working for all or just specifick mailadresses?

Do you have some Sieve filtering on?

Did you also check the spamassasin setup of the receiver?

Did you do a set_permission on your mail?

So either:

#for user specifick
./set_permissions.sh maildir <user> <path/Maildir>

#for all
./set_permissions.sh email

I don’t use spamassasin, I use rspamd and that is not doing any deletions. I was able to see the file being created by doing an ls -l in a while loop while in the maildir directory, but the file disappears almost immediately. So it can't be permissions or that file wouldn't exist even for that brief period of time. It does appear to be user specific, I have spot checked a lot of other users and they do appear to be getting their emails. I did have a sieve set (it was working for years) but I removed it to see if that was the cause as well as removing sieve from the dovecot config, but that still didn't fix the issue. I tried using auditctl to see who/what was deleting the files, but that didn't seem to be much help.

The biggest issue, was this worked for years (20+), until Aug 4th then things started not working correctly. I might have to start hacking dovecot and sprinkle some debug statements to see why this is happening, if I can't find another way to figure out who/what is deleting those emails.

 

[Stije]

I know you use rpamd. But maybe the Spamassasin file has a config. Because rspamd is a drop-in replacement for SpamAssassin, rspamd uses the same config files in the user's directory as SpamAssassin does. So if the spamassin file is edited this also goes to rspamd. So if an option is turned on for example in the spamassin setup of this user/domain with delete mail for example it will still be deleted. That is why I would check the spamassin setup.

if I can't find another way to figure out who/what is deleting those emails.

Are all mails deleted or only from specifick senders? What does your maillog say?

If the mail really is deleted you should see it also in the maillog because it would say it is deleted in the log. And you could see who or what. Could be something simple like an email setup to retreive mail via POP which deletes the mail (some client/gmail/etc.)

 

[mxroute]

but the file disappears almost immediately

That's the key. Some process connecting to your mailbox is moving or deleting the mail after it's written to disk. Change your email account password to automatically log out all email clients, log in only via Roundcube, and test this again. Any email client using POP or IMAP has the authority to delete mail, and email clients may have their own functions that do so automatically. Could be spam filters built into the email client, could be a filter, etc.

 

[toml]

After a lot of debugging, I was able to find the source of the issue. Using strace as well as auditctl, they both told me that the imap process was deleting the emails. As I thought about it, it occurred to me that around the same time I noticed the issue, I had added a "Rule" to my spam filter drone, and the rule was mostly written correctly, it was supposed to match the subject as well as the recipient email address, but unfortunatly I kept the rule saying match "Any" of those two conditions instead of "All" those conditions so it was deleting emails that matched the recipient address.

If anyone has the need to do similar tracing on their systems, here is how I did it, to trace via strace, I needed to capture all the dovecot lmtp processes as well as the main process and strace from there:
#!/bin/sh
mypids=`ps -eaf|grep lmtp |grep -v grep |awk '{ print "-p " $2}'`
cmd="strace -rfttTv -o strace.txt -e trace=creat,unlink,unlinkat,link,linkat,open,openat,close,write "
for mpid in $mypids
do
cmd="$cmd $mpid"
done
echo $cmd
`$cmd`

It traces all the system calls I listed above to a file named strace.txt in the current directory. You can trace all system calls, but it would make this file huge and I didn't need the other calls.

The auditctl command allowed me to see any processes that were writing/renaming/deleting files in a specified directory and sub-directories:
auditctl -a exit,always -S open -S openat -S rename -S close -w /home/$owner/imap/$domainname/$virtual_user/Maildir

Once you have some files written/deleted, you can then use the following command to see the processes:
ausearch -f /home/$owner/imap/$domainname/$virtual_user -i

One more tool I used, was setting debug in dovecot as well as enabling raw logs for lmtp:
add this to the lmtp.conf file and create /tmp/dovecot with the appropriate permissions. It creates raw files of input and output from the lmtp process in the /tmp/dovecot directory.
lmtp_rawlog_dir = /tmp/dovecot


Hopefully this will be helpful to someone in the future.