Vérifier qu'un mail est bien arrivé sur le serveur

Il peut y avoir plusieurs raisons pour qu'un mail supposé arrivé ne soit pas présent dans la boite d'un utilisateur.

Le mail est bloqué par un antispam avant d'arriver sur le serveur BlueMind, dans ce cas il vous faut regarder dans les logs de votre solutions Antispam

Le mail est bloqué dans la queue postifx du serveur BlueMind, cela arrive notamment quand un utilisateur a atteint 100% de son quota, le mail sera dans ce cas placé en attente dans postfix pendant 3 jours. Si au bout de 3 jours il n'a toujours pas réussit à délivrer le mail un message de non-delivery sera envoyé à l'expéditeur. Vous pouvez voir si le mail est présent dans la queue postfix avec la commande :

[root@bluemind ~]# postqueue -p
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
4E4D83AF8E      943 Thu Mar  2 07:10:58  full@bluemind.net
(host 192.168.124.72[192.168.124.72] said: 452 4.2.2 Over quota SESSIONID=<cyrus-4311-1488438658-1> (in reply to RCPT TO command))
                                         full@bluemind.net

Pour débloquer le message, il faut demander à l'utilisateur de supprimer des emails ou augmenter son quota puis attendre que le message soit délivré ou forcer postfix à réessayer de delivrer les emails avec la commande postqueue -f

Si le mail n'est pas bloqué alors vous pouvez trouver les traces de l'arrivée du mail dans les logs de postfix (/var/log/maillog ou /var/log/mail.log) :

Mar  1 20:45:32 bluemind postfix/lmtp[16928]: C5BF3135FAF: to=<user@bluemind.net>, relay=192.168.124.72[192.168.124.72]:2400, delay=0.32, delays=0.21/0.02/0.01/0.09, dsn=2.1.5, status=sent (250 2.1.5 Ok SESSIONID=<cyrus-12823-1488397532-1> [bluemind.net!user.user.INBOX () 2294])

Cette ligne de log montre que le mail identifié par l'id C5BF3135FAF a bien été remis dans la boite de réception de l'utilisateur 'user@bluemind.net' le 1 mars à 20:45.

Vous pouvez trouver plus d'information sur le mail notamment l'adresse de l'expéditeur en recherchant l'id :

[root@bluemind ~]# grep C5BF3135FAF /var/log/maillog
Mar  1 20:45:32 bluemind postfix/smtpd[16923]: C5BF3135FAF: client=smtp.domain.net[192.168.120.30]
Mar  1 20:45:32 bluemind postfix/cleanup[16927]: C5BF3135FAF: message-id=<AM5PR04MB3219A293B59D96973D338B01D2290>
Mar  1 20:45:32 bluemind postfix/qmgr[364]: C5BF3135FAF: from=<user2@domain.net>, size=8386, nrcpt=1 (queue active)
Mar  1 20:45:32 bluemind postfix/lmtp[16928]: C5BF3135FAF: to=<user@bluemind.net>, relay=192.168.124.72[192.168.124.72]:2400, delay=0.32, delays=0.21/0.02/0.01/0.09, dsn=2.1.5, status=sent (250 2.1.5 Ok SESSIONID=<cyrus-12823-1488397532-1> [bluemind.net!user.user.INBOX () 2294])
Mar  1 20:45:32 bluemind postfix/qmgr[364]: C5BF3135FAF: removed

On peut voir ici que c'est user2@domain.net qui est l'expéditeur du mail AM5PR04MB3219A293B59D96973D338B01D2290 et qu'il a bien été délivre à notre utilisateur.

Le message-id est l'identifiant uniquement du message et celui se trouve dans les entêtes de l'email.

Le dernier nombre de la ligne lmtp (ici 2294) correspond à lid du mail dans le dossier INBOX de l'utilisateur, vous pouvez donc trouver le mail dans /var/spool/cyrus/data/b/bluemind_net/b/bluemind.net/u/user/user/2294.

Suivre les déplacements/suppression d'un mail

Les opérations effectuées sur un mail peuvent être retracé via les logs du proxy IMAP bm-ips : /var/log/bm-ips/ips.log

Déplacement d'un mail

Il est possible de retrouver ces informations en recherchant le login de l'utilisateur ou l'id du mail

2017-04-28 06:27:46,844 [vert.x-worker-thread-9] n.b.i.m.n.i.ForwardToMQ INFO - [user2@bluemind.net] mails.copied '7120 "Trash"'
2017-04-28 06:27:46,845 [vert.x-worker-thread-9] n.b.i.m.i.MailboxIndexUpdater INFO - [user2@bluemind.net] onMailsCopied: '7120 "Trash"' => 'OK [COPYUID 1489045668 7120 20] Completed'
2017-04-28 06:27:46,845 [vert.x-worker-thread-9] n.b.i.m.i.MailboxIndexUpdater INFO - [user2@bluemind.net] copy from INBOX/7120 to Trash/20
2017-04-28 06:27:46,846 [vert.x-worker-thread-9] n.b.i.m.i.l.CopyMailRunnable INFO - [user2@bluemind.net][mbox.uid user_entity_634] folder lookup: imap://user/scarpentier@bluemind.net/INBOX
2017-04-28 06:27:46,856 [vert.x-worker-thread-9] n.b.i.m.i.i.CopyMailRunnable INFO - [user2@bluemind.net][mbox.uid user_entity_634] folder lookup: imap://user/scarpentier@bluemind.net/Trash
2017-04-28 06:27:46,871 [vert.x-worker-thread-9] n.b.i.m.MailIndexService INFO - source: 236030:7120, dest: 248259:20

On voit ici que l'utilisateur user2@bluemind.net a déplacé le mail 7210 du dossier INBOX vers le dossier Trash et le mail dans le dossier Trash porte maintenant l'id 20

Suppression d'un mail

De la même manière les logs de bm-ips permettant de voir la suppression d'un mail :

2017-04-28 07:51:15,257 [vert.x-eventloop-thread-1] n.b.i.i.d.c.l.AbstractLoginCP INFO - [user2@bluemind.net] ROUNDCUBE srv: 192.168.150.150, tag A0001 in 47ms.
2017-04-28 07:51:15,273 [vert.x-worker-thread-7] n.b.i.m.i.MailboxIndexUpdater INFO - [user2@bluemind.net] onFlagsChanged: 
2017-04-28 07:51:15,277 [vert.x-worker-thread-7] n.b.i.m.i.i.FlagsChangeRunnable INFO - [user2@bluemind.net][mbox.uid user_entity_23] folder lookup: imap://user/user2@bluemind.net/OTB
2017-04-28 07:51:15,284 [vert.x-worker-thread-7] n.b.i.m.MailIndexService INFO - change flags in imap://user/user2@bluemind.net/OTB 42:2818
2017-04-28 07:51:15,284 [vert.x-worker-thread-7] n.b.i.m.MailIndexService INFO - Bulk START on index mailspool_alias_user_entity_23
2017-04-28 07:51:15,340 [vert.x-worker-thread-7] n.b.i.m.MailIndexService INFO - Bulk END (1)
2017-04-28 07:51:15,340 [vert.x-worker-thread-7] n.b.i.m.MailIndexService INFO - updated emails 1
2017-04-28 07:51:15,340 [vert.x-worker-thread-7] n.b.i.m.i.i.FlagsChangeRunnable INFO - Update time is 56ms.
2017-04-28 07:51:15,340 [vert.x-worker-thread-7] n.b.i.m.i.i.FlagsChangeRunnable INFO - [user2@bluemind.net][OTB] Reindexing done in 67ms.
2017-04-28 07:51:15,347 [vert.x-eventloop-thread-1] n.b.i.v.i.RemoteDataHandler INFO - [user2@bluemind.net] imap time: 9ms, total time: 83ms, overhead: 73ms.
2017-04-28 07:51:15,354 [vert.x-worker-thread-17] n.b.i.m.i.MailboxIndexUpdater INFO - [OTB] onMailsExpunged: '2818'
2017-04-28 07:51:15,359 [vert.x-worker-thread-17] n.b.i.m.i.i.UidExpungeRunnable INFO - [user2@bluemind.net][mbox.uid user_entity_23] folder lookup: imap://user/user2@bluemind.net/OTB
2017-04-28 07:51:15,368 [vert.x-worker-thread-17] n.b.i.m.MailIndexService INFO - expunge: imap://user/user2@bluemind.net/OTB 2818
2017-04-28 07:51:15,368 [vert.x-worker-thread-17] n.b.i.m.MailIndexService INFO - Bulk START on index mailspool_alias_user_entity_23
2017-04-28 07:51:15,376 [vert.x-worker-thread-17] n.b.i.m.MailIndexService INFO - Bulk END (1)
2017-04-28 07:51:15,376 [vert.x-worker-thread-17] n.b.i.m.MailIndexService INFO - expunge imap://user/user2@bluemind.net/OTB (2818) : 1 deleted
2017-04-28 07:51:15,376 [vert.x-worker-thread-17] n.b.i.m.i.i.UidExpungeRunnable INFO - [user2@bluemind.net][OTB] Reindexing done in 22ms.