Hello.
I'm tracking a weird case where dovecot (it's 2.3.21.1) looses incoming
emails. Email is delivered over LMTP with full success (in theory).
From lmtp raw log:
1742822341.735762 250 2.0.0 <examplelogin@mbox> +LpAG8Vb4Wc9OAAA9fPEKQ Saved
1742822341.735918 221 2.0.0 Bye
Log says it got saved:
Mar 24 14:19:01 mbox dovecot[22785]: lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>,
msgid=<XYZ...1611.EURP189.PROD.OUTLOOK.COM>,
storage_id=1742822341.M462393P14397.mbox,S=139039,W=141006,
delivery_status=saved mail to INBOX
There is a file name but
# find /var/mail/examplelogin/ -name '1742822341.M462393P14397.mbox*'
#
nothing. Well, someone could delete or move this email, right? But no,
that's not the case, only pop3 sessions around:
Mar 24 14:18:43 mbox dovecot[22785]: pop3(examplelogin): pid=<24041>
session=<rX98cRYxIvlTDCet>, Disconnected: Logged out top=0/0, retr=0/0, del=0/20,
size=5204114, in=24, out=1002
Mar 24 14:19:01 mbox dovecot[22785]: lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, msgid=<XYZ...1611.EURP189.PROD.OUTLOOK.COM>,
storage_id=1742822341.M462393P14397.mbox,S=139039,W=141006, delivery_status=saved mail to INBOX
Mar 24 14:19:43 mbox dovecot[22785]: pop3-login: Login: user=<examplelogin>,
method=PLAIN, rip=1.1.1.1, rport=63799, lip=2.2.2.2, lport=110, mpid=27238,
session=<GPgZdRYxN/lTDCet>
Mar 24 14:19:44 mbox dovecot[22785]: pop3(examplelogin): pid=<27238>
session=<GPgZdRYxN/lTDCet>, Disconnected: Logged out top=0/0, retr=0/0, del=0/20,
size=5204114, in=24, out=1002
Note the same number of total mails in del log before and after
problematic mail delivery - "del=0/20", so dovecot doesn't see that new
mail (there are few pop3 logins after that - all with del=0/20)
So the conclusion is that the file, with email, was not created on the
filesystem.
LMTP raw session log, debug session log, nothing weird - below.
BUT there is one thing:
Debug: Mailbox INBOX: saving UID 0: Opened mail because: snippet (Mail
not cached, highest cached seq=20 uid=31: reset_id=1742577355)
"Opened mail because: snippet " - what does this mean?
Out of 50k mails delivered only 160 have that "Opened mail because:
snippet" and by that I mean that logged for lmtp like:
Mar 24 07:25:18 lmtp(xyz): pid=<28535> session=<SPx6Ds764Gd3bwAA9fPEKQ>,
Debug: Mailbox INBOX: saving UID 0: Opened mail because: snippet (Mail
not cached, highest cached seq=291 uid=4094: reset_id=1579231568)
The rest have "UID 0: Opened mail because: mail stream".
Started looking at these snipped entries. It seems that almost every
mail with this logged is missing on the filesystem(!).
Huh, what could be happening here?
debug log (is there a way to enable even more detailed/low level log?):
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: auth-master: userdb
lookup(examplelogin@mbox): Started userdb lookup
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: auth-master: userdb
lookup(examplelogin@mbox): auth USER input: examplelogin home=/var/mail/examplelogin/
mail=maildir:/var/mail/examplelogin/:CONTROL=/var/lib/dovecot/control/examplelogin:VOLATILEDIR=/var/lib/dovecot/control/examplelogin:INDEX=/var/lib/dovecot/control/examplelogin
uid=1234 gid=7890 sieve_enabled=no
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: auth-master: userdb
lookup(examplelogin@mbox): Finished userdb lookup (username=examplelogin
home=/var/mail/examplelogin/
mail=maildir:/var/mail/examplelogin/:CONTROL=/var/lib/dovecot/control/examplelogin:VOLATILEDIR=/var/lib/dovecot/control/examplelogin:INDEX=/var/lib/dovecot/control/examplelogin
uid=1234 gid=7890 sieve_enabled=no)
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: changed username to examplelogin
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: lmtp-server: conn unix:pid=25252,uid=8 [89]:
rcpt examplelogin@mbox: Added userdb setting:
mail=maildir:/var/mail/examplelogin/:CONTROL=/var/lib/dovecot/control/examplelogin:VOLATILEDIR=/var/lib/dovecot/control/examplelogin:INDEX=/var/lib/dovecot/control/examplelogin
Mar 24 14:19:01 lmtp(examplelogin@mbox): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: lmtp-server: conn unix:pid=25252,uid=8 [89]:
rcpt examplelogin@mbox: Added userdb setting: plugin/sieve_enabled=no
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Effective uid=1234, gid=7890,
home=/var/mail/examplelogin/
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota root: name=Calkowita przestrzen dla
serwera backend=fs args=group
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota grace: root=Calkowita przestrzen dla
serwera bytes=0 (10%)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota root: name=Twoja przestrzen e-mail
backend=fs args=user
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota grace: root=Twoja przestrzen e-mail
bytes=0 (10%)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Namespace inbox: type=private,
prefix=INBOX., sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes
location=maildir:/var/mail/examplelogin/:CONTROL=/var/lib/dovecot/control/examplelogin:VOLATILEDIR=/var/lib/dovecot/control/examplelogin:INDEX=/var/lib/dovecot/control/examplelogin
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: maildir++: root=/var/mail/examplelogin,
index=/var/lib/dovecot/control/examplelogin, indexpvt=,
control=/var/lib/dovecot/control/examplelogin, inbox=/var/mail/examplelogin, alt=
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota add mailbox dir =
/var/mail/examplelogin
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota block device =
/dev/mapper/vg_sys-lv_home
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota mount point = /home
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota mount type = xfs
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Namespace : type=private, prefix=, sep=,
inbox=no, hidden=yes, list=no, subscriptions=no location=fail::LAYOUT=none
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: none: root=, index=, indexpvt=, control=,
inbox=, alt=
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: fts: Indexes disabled for namespace ''
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota: quota_over_flag check:
quota_over_script unset - skipping
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota: quota_over_flag check:
quota2_over_script unset - skipping
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: User session is finished
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Effective uid=1234, gid=7890,
home=/var/mail/examplelogin/
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota root: name=Calkowita przestrzen dla
serwera backend=fs args=group
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota grace: root=Calkowita przestrzen dla
serwera bytes=0 (10%)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota root: name=Twoja przestrzen e-mail
backend=fs args=user
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Quota grace: root=Twoja przestrzen e-mail
bytes=0 (10%)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Namespace inbox: type=private,
prefix=INBOX., sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes
location=maildir:/var/mail/examplelogin/:CONTROL=/var/lib/dovecot/control/examplelogin:VOLATILEDIR=/var/lib/dovecot/control/examplelogin:INDEX=/var/lib/dovecot/control/examplelogin
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: maildir++: root=/var/mail/examplelogin,
index=/var/lib/dovecot/control/examplelogin, indexpvt=,
control=/var/lib/dovecot/control/examplelogin, inbox=/var/mail/examplelogin, alt=
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota add mailbox dir =
/var/mail/examplelogin
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota block device =
/dev/mapper/vg_sys-lv_home
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota mount point = /home
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota-fs: fs quota mount type = xfs
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Namespace : type=private, prefix=, sep=,
inbox=no, hidden=yes, list=no, subscriptions=no location=fail::LAYOUT=none
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: none: root=, index=, indexpvt=, control=,
inbox=, alt=
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: fts: Indexes disabled for namespace ''
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota: quota_over_flag check:
quota_over_script unset - skipping
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: quota: quota_over_flag check:
quota2_over_script unset - skipping
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: duplicate db: Initialize
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: sieve: Pigeonhole version 0.5.21.1
(49005e73) initializing
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: sieve: include: sieve_global is not set; it
is currently not possible to include `:global' scripts.
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: sieve: Sieve is disabled for this user
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: duplicate db: Cleanup
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Mailbox INBOX: Mailbox opened
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Mailbox INBOX: saving UID 0: Opened mail
because: snippet (Mail not cached, highest cached seq=20 uid=31: reset_id=1742577355)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Mailbox INBOX: Adding field hdr.Subject to
cache for the first time (uid=0)
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: Mailbox INBOX: Mailbox opened
Mar 24 14:19:01 lmtp(examplelogin): pid=<14397>
session=<+LpAG8Vb4Wc9OAAA9fPEKQ>, Debug: User session is finished
ps. logins, uid, gid changed to example values
--
Arkadiusz Miśkiewicz, arekm / ( maven.pl | pld-linux.org )
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-le...@dovecot.org
