Resolved Some email not arriving in Roundcube (but passes MagicSpam)

[Liv]

Hi!

So I've got this very weird thing that some email is visible in the MagicSpam log and marked as OK (HAM), but somehow doesn't arrive in RoundCube.

I've tried the following:

1. Deactivating MagicSpam.
2. Deactivating SpamAssassin-spamfilter in Plesk.
3. Checked the Roundcube spam folder of this particular mailbox.

It's very strange since it only applies to some emails, this email was from google.com which in general should work and arrive.

Is there a way to find these emails? Or a way to see a maillog in Plesk or CentOS and figure out where these incoming message get stuck and how to allow them to pass?

Setup:
CentOS Linux 7.4.1708 (Core)‬
Product Plesk Onyx
Version 17.5.3 Update #38

 

[TomBoB]

do they show up if you search for them (top right corner in webmail) ?

 

[Liv]

No unfortunately not..

 

[danami]

> Is there a way to find these emails? Or a way to see a maillog in Plesk or CentOS and figure out where these incoming message get stuck and how to allow them to pass?

You can look in your servers mail log :

zgrep <email_address> /var/log/maillog*

 

[Liv]

Thanks for the suggestion, I found them in the log:

/var/log/maillog.processed:Jan 25 20:10:37 vps postfix/qmgr[5251]: 6B79F118A534: from=<[email protected]>, size=4377, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 25 20:10:37 vps postfix-local[9624]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
 dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 25 20:13:34 vps postfix/qmgr[5251]: A52311225AB5: from=<[email protected]>, size=4385, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 25 20:13:34 vps postfix-local[9903]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:22:49 vps postfix/qmgr[5251]: 1AF0610539CE: from=<[email protected]>, size=4646, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 26 11:22:49 vps postfix-local[21406]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:34:54 vps postfix/qmgr[5251]: 8DE9C120AF96: from=<[email protected]>, size=4642, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 26 11:34:54 vps postfix-local[22804]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:34:58 vps postfix/qmgr[5251]: 86566120AF96: from=<[email protected]>, size=4650, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 26 11:34:58 vps postfix-local[22812]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:42:30 vps postfix/qmgr[5251]: F114910FDA66: from=<[email protected]>, size=4644, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 26 11:42:30 vps postfix-local[23900]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:43:45 vps postfix/qmgr[5251]: D316010FDA66: from=<[email protected]>, size=4642, nrcpt=1 (queue active)
/var/log/maillog.processed:Jan 26 11:43:45 vps postfix-local[24013]: postfix-local: [email protected], [email protected], dirname=/var/qmail/mailnames
/var/log/maillog.processed:Jan 26 11:46:01 vps postfix/qmgr[5251]: 2EC42120336E: from=<[email protected]>, size=4649, nrcpt=1 (queue active)

Well and more of the same records, I've tried quite a few times.

What does this mean, does it mean they get in a queue somehow?

 

[danami]

Well that tells you that the email actually made it to your server. To get a complete picture of what happened to the mail you need to search by queueids... This might help:
How to search mail logs effectively with `RegEx`

 

[Liv]

Ok thanks for that one!

I got them with these commands:

 grep 'to=<[email protected]>' /var/log/maillog | cut -d ' ' -f 6

I noticed the ID's. And to see the entire log:

grep 'to=<[email protected]>' /var/log/maillog | cut -d ' ' -f 6 | grep -f - /var/log/maillog

I got this as a result:

Jan 29 14:37:25 vps postfix/smtpd[1588]: 31387120DD92: client=mail-oi0-x22f.google.com[2607:f8b0:4003:c06::22f]
Jan 29 14:37:25 vps postfix/cleanup[2802]: 31387120DD92: message-id=<CAMDeNSDuAGBuBh1sMmAoDAQvGAr3mK5BqW3M4gGOXqKf9h9PMA@mail.gmail.com>
Jan 29 14:37:25 vps postfix/qmgr[3381]: 31387120DD92: from=<[email protected]>, size=4643, nrcpt=1 (queue active)
Jan 29 14:37:25 vps postfix/pipe[2804]: 31387120DD92: to=<[email protected]>, relay=plesk_virtual, delay=0.56, delays=0.29/0.01/0/0.26, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jan 29 14:37:25 vps postfix/qmgr[3381]: 31387120DD92: removed

I've tried with MagicSpam turned off, it's the same result. Somehow the message passes MagicSpam and still get's removed:

Jan 29 14:40:52 vps postfix/smtpd[3434]: CA64D120DD9D: client=mail-oi0-x229.google.com[2607:f8b0:4003:c06::229]
Jan 29 14:40:53 vps postfix/cleanup[3561]: CA64D120DD9D: message-id=<CAMDeNSAQR2796s+hP-6dSGmc1HcCYWaaL6wfDj_Q2dj9=7VQRw@mail.gmail.com>
Jan 29 14:40:53 vps postfix/qmgr[3381]: CA64D120DD9D: from=<[email protected]>, size=4645, nrcpt=1 (queue active)
Jan 29 14:40:53 vps postfix/pipe[3570]: CA64D120DD9D: to=<[email protected]>, relay=plesk_virtual, delay=1.1, delays=0.28/0/0/0.82, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jan 29 14:40:53 vps postfix/qmgr[3381]: CA64D120DD9D: removed

Any tips?

 

[danami]

The message wasn't removed. It was delivered to the mailbox as it should (status=sent (delivered via plesk_virtual service)). I would check and see if there are any sieve rules enabled on the account that are moving the message to another folder or performing other operations.

 

[Liv]

I figured it out (weehoeee!) trying to fix something else..

The issue was DKIM.. eh yea what? So OpenDKIM wasn't running for some reason, and somehow I guess since the mailserver couldnt properly read the DKIM the message got lost somewhere. Or some totally other explanation. Anyhow, it's back on and I received the messages.

See the difference, without OpenDKIM:

Jan 29 14:40:52 vps postfix/smtpd[3434]: CA64D120DD9D: client=mail-oi0-x229.google.com[2607:f8b0:4003:c06::229]
Jan 29 14:40:53 vps postfix/cleanup[3561]: CA64D120DD9D: message-id=<CAMDeNSAQR2796s+hP-6dSGmc1HcCYWaaL6wfDj_Q2dj9=7VQRw@mail.gmail.com>
Jan 29 14:40:53 vps postfix/qmgr[3381]: CA64D120DD9D: from=<[email protected]>, size=4645, nrcpt=1 (queue active)
Jan 29 14:40:53 vps postfix/pipe[3570]: CA64D120DD9D: to=<[email protected]>, relay=plesk_virtual, delay=1.1, delays=0.28/0/0/0.82, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jan 29 14:40:53 vps postfix/qmgr[3381]: CA64D120DD9D: removed

And with OpenDKIM:

Jan 29 19:55:02 vps postfix/smtpd[22888]: 8485F10F782C: client=mail-ot0-x22d.google.com[2607:f8b0:4003:c0f::22d]
Jan 29 19:55:02 vps postfix/cleanup[23118]: 8485F10F782C: message-id=<CAMDeNSDSfaxvCJ_7JHwQqXk=fpaLAxa8G_Wvdgv8afTTq2hZRQ@mail.gmail.com>
Jan 29 19:55:02 vps opendkim[855]: 8485F10F782C: mail-ot0-x22d.google.com [2607:f8b0:4003:c0f::22d] not internal
Jan 29 19:55:02 vps opendkim[855]: 8485F10F782C: not authenticated
Jan 29 19:55:02 vps opendkim[855]: 8485F10F782C: DKIM verification successful
Jan 29 19:55:02 vps postfix/qmgr[3381]: 8485F10F782C: from=<[email protected]>, size=4609, nrcpt=1 (queue active)
Jan 29 19:55:03 vps postfix/pipe[23119]: 8485F10F782C: to=<[email protected]>, relay=plesk_virtual, delay=1.3, delays=0.37/0.01/0/0.91, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jan 29 19:55:03 vps postfix/qmgr[3381]: 8485F10F782C: removed

Thanks for the tips on the maillog stuff!