Question Incoming, received and verified but not delivered e-mails

[learning_curve]

A new type of 'challenge' that we noticed tonight... Some e-mails (from Google of all people re: one of our domain's api's setup criteria) have simply disappeared somewhere inside Plesk. Eight were sent and all eight cleared / were verified as 'ham" within Magic Spam. This can all clearly be seen within the Magic Spam logs.

But....only six of the eight made it into the correct e-mail inboxes. The missing two e-mails are not anywhere else (e.g. spam / junk boxes etc) They were not put in jail within Fail2ban checks and they were not sent from any firewalled IP adresses...Where could they have gone and why?

 

[IgorG]

The story worthy of the pen of Arthur Conan Doyle.
But I think that even Sherlock Holmes would ask you for detailed maillogs to start the research. It is possible that as an assistant he would have invited Dr. Watson, sorry, I mean @MagicSpam12 ...

 

[learning_curve]

...Sherlock Holmes would ask you for detailed maillogs to start the research...

Shelock Holmes would have said "...It's elementary my dear Watson" but we don't agree...

2018-06-04 16:12:42 magicspam-daemon[40056]: HAM: mua=no,ip=[209.85.214.71:mail-it0-f71.google.com],helo=<mail-it0-f71.google.com>,from=<36fyvwxgkbmkv33v0t1dq97x2t77-236t40dv33v0t.r31832dppp-6prx2v.9z@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 16:34:53 magicspam-daemon[41444]: HAM: mua=no,ip=[209.85.220.197:mail-qk0-f197.google.com],helo=<mail-qk0-f197.google.com>,from=<3hfwvwxmkbakwx0nyu7-vjy1-r113n1pxxpun.lxv2xw7jjj-0jlrwp.3t@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 16:36:13 magicspam-daemon[41564]: HAM: mua=no,ip=[209.85.214.70:mail-it0-f70.google.com],helo=<mail-it0-f70.google.com>,from=<3bfwvwxmkbfkefi5gcp-d1gj-9jjl5j7ff7c5.3fdkfep111-i139e7.lb@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 16:36:33 magicspam-daemon[41599]: HAM: mua=no,ip=[209.85.220.199:mail-qk0-f199.google.com],helo=<mail-qk0-f199.google.com>,from=<3gfwvwxmkbg0yzcpawj-xlad-tddfpdrzzrwp.nzxezyjlll-clntyr.fv@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 16:36:56 magicspam-daemon[41628]: HAM: mua=no,ip=[209.85.220.197:mail-qk0-f197.google.com],helo=<mail-qk0-f197.google.com>,from=<3l1wvwxmkbiqvwzmxt6-uix0-q002m0owwotm.kwu1wv6iii-zikqvo.2s@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 16:37:15 magicspam-daemon[41654]: HAM: mua=no,ip=[209.85.214.71:mail-it0-f71.google.com],helo=<mail-it0-f71.google.com>,from=<3qlwvwxmkbjcefi5gcp-d1gj-9jjl5j7ff7c5.3fdkfep111-i139e7.lb@scoutcamp.bounces.google.com>,rcpt=<*123*@my*domain*.com>
2018-06-04 17:31:01 magicspam-daemon[45383]: HAM: mua=no,ip=[74.125.83.71:mail-pg0-f71.google.com],helo=<mail-pg0-f71.google.com>,from=<3q2kvwwgtb0oz0-3q1xamoo06z54.s00sxq.o0y4q37uoqmmm-3mouzs.6w@idverification.bounces.google.com>,rcpt=<*xyz*@my*domain*.com>
2018-06-04 17:36:05 magicspam-daemon[46058]: HAM: mua=no,ip=[209.85.160.72:mail-pl0-f72.google.com],helo=<mail-pl0-f72.google.com>,from=<3dgovwwgtb30op-sfqmzbddpvout.hpphmf.dpntfswjdfbbb-sbdjoh.vl@idverification.bounces.google.com>,rcpt=<*xyz*@my*domain*.com>

^^ That's the eight incoming but (as described) there was only six survivors once we looked in the inboxes. The first six were sent to one e-mail address, the last two are to another e-mail address but... both e-mail addresses are setup and hosted via Plesk and both are on the same domain, on the same server (Only the receiving e-mail addresses are sanitised for foum use)

Out of interest, we tried the last two Google API exercises again, but with the same results i.e. Totally fine and correct within MagicSpam, but never appearing within the actual e-mail inbox...

2018-06-05 02:03:09 magicspam-daemon[16430]: HAM: mua=no,ip=[209.85.192.197:mail-pf0-f197.google.com],helo=<mail-pf0-f197.google.com>,from=<3s-evwwgtb0qtu-xkvr4giiu0tzy.muumrk.iusykx1oikggg-xgiotm.0q@idverification.bounces.google.com>,rcpt=<*xyz*@my*domain*.com>
2018-06-05 02:05:29 magicspam-daemon[17127]: HAM: mua=no,ip=[74.125.83.71:mail-pg0-f71.google.com],helo=<mail-pg0-f71.google.com>,from=<31-evwwgtb9a9a-d0b7kwyyag9fe.2aa270.ya8e0dh4y0www-dwy492.g6@idverification.bounces.google.com>,rcpt=<*xyz*@my*domain*.com>

Our first guess is... this isn't to do with any failing by Dr Watson ( @MagicSpam12 ) it's something else, that's happening AFTER his initial investigation Comments observations welcome from all...

 

[Monty]

Well, it would be interesting to see your Postfix logs. Can you post those logs too?

 

[learning_curve]

Ha! Thanks @EmmanuelD It was indeed; "...elementary my dear Watson..."

It's an odd one though... The two missing two e-mails, both appear to have failed the Plesk Mail Server (DMARC filter) DKIM test and so they were then deleted. This is the correct process and matches the settings in our Plesk setup. It's also why these e-mails passed MagicSpam, but didn't then get any further, as we can see in the log extract.... These two e-mails remember, are both from, wait for it Google so a DKIM failure is pretty unlikely (but not impossible)

What's odd is that the spamassassin filter sees them as DKIM_SIGNED,DKIM_VALID but then the DMARC filter reports DKIM record was not found in Authentication-Results which is kind of contradictory in many ways...

Thoughts anyone?

Here's the first e-mail as an example (sanitised extract from Postfix log)

Jun  4 17:31:01 seserv1 postfix/smtpd[45328]: 1ADF98AEE1: client=mail-pg0-f71.google.com[74.125.83.71]
Jun  4 17:31:01 seserv1 postfix/cleanup[45385]: 1ADF98AEE1: message-id=<[email protected]>
Jun  4 17:31:01 seserv1 check-quota[45388]: Starting the check-quota filter...
Jun  4 17:31:01 seserv1 /usr/lib64/plesk-9.0/psa-pc-remote[984]: handlers_stderr: SKIP
Jun  4 17:31:01 seserv1 /usr/lib64/plesk-9.0/psa-pc-remote[984]: SKIP during call 'check-quota' handler
Jun  4 17:31:01 seserv1 spf[45389]: Starting the spf filter...
Jun  4 17:31:01 seserv1 spf[45389]: SPF result: pass
Jun  4 17:31:01 seserv1 spf[45389]: SPF status: PASS
Jun  4 17:31:01 seserv1 /usr/lib64/plesk-9.0/psa-pc-remote[984]: handlers_stderr: PASS
Jun  4 17:31:01 seserv1 /usr/lib64/plesk-9.0/psa-pc-remote[984]: PASS during call 'spf' handler
Jun  4 17:31:01 seserv1 postfix/qmgr[2068]: 1ADF98AEE1: from=<3Q2kVWwgTB0oz0-3q1xAmoo06z54.s00sxq.o0y4q37uoqmmm-3mouzs.6w@idverification.bounces.google.com>, size=7698, nrcpt=1 (queue active)
Jun  4 17:31:01 seserv1 postfix-local[45391]: postfix-local: from=3Q2kVWwgTB0oz0-3q1xAmoo06z54.s00sxq.o0y4q37uoqmmm-3mouzs.6w@idverification.bounces.google.com, to=*xyz*@my*domain*.com, dirname=/var/qmail/mailnames
Jun  4 17:31:01 seserv1 spamassassin[45392]: Starting the spamassassin filter...
Jun  4 17:31:01 seserv1 spamd[53223]: spamd: connection from localhost.localdomain [127.0.0.1]:43180 to port 783, fd 5
Jun  4 17:31:01 seserv1 spamd[53223]: spamd: using default config for *xyz*@my*domain*.com: /var/qmail/mailnames/my*domain.com/*xyz*/.spamassassin/user_prefs
Jun  4 17:31:01 seserv1 spamd[53223]: spamd: processing message <[email protected]> for *xyz*@my*domain*.com:30
Jun  4 17:31:01 seserv1 postfix/smtpd[45328]: disconnect from mail-pg0-f71.google.com[74.125.83.71] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jun  4 17:31:03 seserv1 spamd[53223]: spamd: clean message (2.7/7.0) for *xyz*@my*domain*.com:30 in 1.8 seconds, 8276 bytes.
Jun  4 17:31:03 seserv1 spamd[53223]: spamd: result: . 2 - DKIM_SIGNED,DKIM_VALID,HTML_MESSAGE,MPART_ALT_DIFF,RCVD_IN_DNSWL_NONE,RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL,T_DKIMWL_WL_MED,T_FILL_THIS_FORM_SHORT,URI_TRY_3LD scantime=1.8,size=8276,user=*xyz*@my*domain*.com,uid=30,required_score=7.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=43180,mid=<[email protected]>,autolearn=no autolearn_force=no
Jun  4 17:31:03 seserv1 dmarc[45395]: Starting the dmarc filter...
Jun  4 17:31:03 seserv1 dmarc[45395]: DKIM record was not found in Authentication-Results:
Jun  4 17:31:03 seserv1 dmarc[45395]: DMARC: REJECT message for *xyz*@my*domain*.com
Jun  4 17:31:03 seserv1 postfix-local[45391]: message discarded by a mail handler
Jun  4 17:31:03 seserv1 postfix/pipe[45390]: 1ADF98AEE1: to=<*xyz*@my*domain*.com>, relay=plesk_virtual, delay=2.7, delays=0.82/0.02/0/1.8, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jun  4 17:31:03 seserv1 postfix/qmgr[2068]: 1ADF98AEE1: removed

 

[Monty]

OK, that's a good starting point. Now we at least know that the DMARC filter rejected the mails.
Just a wild guess, but maybe have a look at this: Unable to receive an email from Yahoo with DMARC enabled: DMARC: REJECT message

If that doesn't help then please to a "plesk repair mail"

 

[learning_curve]

Hmmm Close but no cigar The fix contained within the link to yahoo e-mails failing was/is how our Postfix main.cf was/is setup anyway, so this made wasn't going to make any difference we thought. The "plesk repair mail" result was:

# plesk repair mail

Repairing the mail server configuration
 
  Reconfigure all domains and mailboxes? [Y/n] y
    Reconfiguring all domains and mailboxes ......................... [OK]

Error messages: 0; Warnings: 0; Errors resolved: 0

So nothing immediatley visible here either. Having run through the Google process again, the last relevant part of the postfix log shows effectively the same result (i.e. the e-mail doesn't make it into the inbox) but it's worded differently now...

Jun  6 10:16:55 secserv1 spamassassin[38483]: Starting the spamassassin filter...
Jun  6 10:16:55 secserv1 spamd[37472]: spamd: connection from localhost.localdomain [127.0.0.1]:57774 to port 783, fd 5
Jun  6 10:16:55 secserv1 spamd[37472]: spam: using default config for *xyz*@my*domain*.com: /var/qmail/mailnames/my*domain*.com/*xyz*/.spamassassin/user_prefs
Jun  6 10:16:55 secserv1 spamd[37472]: spamd: processing message <[email protected]> for *xyz*@my*domain*.com.uk:30
Jun  6 10:16:55 secserv1 postfix/smtpd[38455]: disconnect from mail-pl0-f70.google.com[209.85.160.70] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jun  6 10:16:56 secserv1 spamd[37472]: spamd: clean message (2.7/7.0) for *xyz*@my*domain*.com:30 in 0.9 seconds, 8279 bytes.
Jun  6 10:16:56 secserv1 spamd[37472]: spamd: result: . 2 - DKIM_SIGNED,DKIM_VALID,HTML_MESSAGE,MPART_ALT_DIFF,RCVD_IN_DNSWL_NONE,RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL,T_DKIMWL_WL_MED,T_FILL_THIS_FORM_SHORT,URI_TRY_3LD scantime=0.9,size=8279,user=*xyz*@my*domain*.com,uid=30,required_score=7.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=57774,mid=<[email protected]>,autolearn=no autolearn_force=no
Jun  6 10:16:56 secserv1 dk_check[38486]: Starting the dk_check filter...
Jun  6 10:16:56 secserv1 dk_check[38486]: DKIM verify result: DKIM verification (d=google.com, 2048-bit key) succeeded
Jun  6 10:16:56 secserv1 dmarc[38487]: Starting the dmarc filter...
Jun  6 10:16:56 secserv1 dmarc[38487]: DMARC: REJECT message for *xyz*@my*domain*.com
Jun  6 10:16:56 secserv1 postfix-local[38482]: message discarded by a mail handler
Jun  6 10:16:56 secserv1 postfix/pipe[38481]: C800B13CA7D: to=<*xyz*@my*domain*.com>, relay=plesk_virtual, delay=1.8, delays=0.85/0.02/0/0.96, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jun  6 10:16:56 secserv1 postfix/qmgr[38231]: C800B13CA7D: removed

 

[SamirM]

I am facing the same issues since a few days now, random mails are not being delivered though its marked as HAM in the magicspam logs. My server runs QMAIL, any solution

 

[learning_curve]

I am facing the same issues since a few days now, random mails are not being delivered though its marked as HAM in the magicspam logs. My server runs QMAIL, any solution

We didn't actually solve this way back then, but we did manage a workaround for those specific e-mails, not within Plesk, but by altering the way we used the Google API.

Since then, we've changed servers and server OS from CentOS to Ubuntu and upgraded from Plesk 17.5.3 to Plesk 17.8.11 plus, we've made a lot of Plesk updates and made quite a few of our own modifications too.... The result is that it doesn't happen any more (to us anyway) so we haven't wasted any time trying to find out why it did, back then.

For your own interest, did you check your Plesk Mail Server (DMARC filter) DKIM test results in the logs and were the results from a fully trusted sender, the same as ours were back then? If so, you may need to submit a support request direct to Plesk, as it will probably be a detailed analyisis job to solve it

 

[SamirM]

I think we found a solution, both the recepient as well as the sender had issues in the SPF record, which is surprising atleast from the sender's point of view, since they were setup right.
After both re created the SPF records, nor mal deleivery resumed