thr3ads.net - dovecot - Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received [Dec 2020]

If this information is useful, please help other people find it:
Share via:

Steve Akerman

2020-Dec-10 13:58 UTC

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

Good afternoon

I have been using Dovecot with great success for several months now with one
problem:

I have received several messages (3 to date out of a much larger number) which
cause Dovecot LMTP to drop the connection with sendmail after only receiving the
first part of the message.

Dovecot saves the first part to INBOX, and then drops the link with sendmail as
it sees the rest of the data from sendmail as new (and invalid) commands

Sendmail sees the delivery as unsuccessful and requeues the message, so the
cycle continues until i kill the queue

These messages are all Multipart MIME

I have attached an extract from the log which shows the above sequence

Finally, I have kept one such message from the sendmail queue (df and qf) should
this be useful, but prefer not to post here as not sanitised

Any help in correcting my configuration would be appreciated.

Thanks

Steve


MAIL LOG extract
-------------------------

Dec  9 12:00:10 phone dovecot[179]: lmtp(20774): Connect from local
Dec  9 12:00:10 phone sm-mta-rx[20764]: STARTTLS=client, relay=localhost,
version=TLSv1.3, verify=OK, cipher=TLS_AES_256_GCM_SHA384, bits=256/256
Dec  9 12:00:10 phone dovecot[179]: lmtp(20775): Connect from local
Dec  9 12:00:10 phone sm-mta-rx[20763]: STARTTLS=client, relay=localhost,
version=TLSv1.3, verify=OK, cipher=TLS_AES_256_GCM_SHA384, bits=256/256
Dec  9 12:00:10 phone dovecot[179]:
lmtp(*********)<20775><8EieKDqu0F8nUQAA0J78UA>:
msgid=<39113a86-fdbb-4cea-b1c3-d225dff93328 at info.ameli.fr
<mailto:39113a86-fdbb-4cea-b1c3-d225dff93328 at info.ameli.fr>>: saved
mail to INBOX
Dec  9 12:00:10 phone dovecot[179]: lmtp(20775): Disconnect from local: Too many
invalid commands. (state=READY)
Dec  9 12:00:10 phone sm-mta-rx[20763]: STARTTLS: write error=syscall error
(-1), errno=32, get_error=error:00000000:lib(0):func(0):reason(0), retry=1,
ssl_err=5
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: SYSERR(root): timeout
writing message to localhost: Broken pipe
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   0: fl=0x0, mode=20666:
CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   1: fl=0x1, mode=20666:
CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   2: fl=0x1, mode=20666:
CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   3: fl=0x4002,
mode=100600: dev=1/2, ino=26089780, nlink=1, u/gid=0/23, size=2041
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   4: fl=0x0, mode=20666:
CHR: dev=30/1306024, ino=575, nlink=1, u/gid=0/0, size=0
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   5: fl=0x2,
mode=140666: SOCK localhost->[[UNIX: /var/run/mDNSResponder]]
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   6: fl=0x0,
mode=100640: dev=1/2, ino=25887976, nlink=1, u/gid=0/23, size=12288
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   7: fl=0x0,
mode=100640: dev=1/2, ino=25887976, nlink=1, u/gid=0/23, size=12288
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   8: fl=0x0,
mode=100600: dev=1/2, ino=26088246, nlink=1, u/gid=0/23, size=58024
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   9: fl=0x6,
mode=140444: SOCK localhost->(Invalid argument)
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  10: fl=0x6,
mode=140444: SOCK localhost->(Invalid argument)
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  11: fl=0x0,
mode=100640: dev=1/2, ino=25768590, nlink=1, u/gid=0/23, size=12288
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  12: fl=0x0,
mode=100640: dev=1/2, ino=25768590, nlink=1, u/gid=0/23, size=12288
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: MCI at 0x0: NULL
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: MCI at 0x7fae2c814818:
flags=26404c<CACHED,ESMTP,8BITMIME,INMIME,ENHSTAT,PIPELINED,TLSACT>,
errno=32, herrno=0, exitstat=75, state=8, pid=0, maxsize=0, phase=client DATA
354, mailer=dovecot, status=4.4.2, rstatus=(null), host=localhost, lastuse=Wed
Dec  9 12:00:10 2020\n
Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:
to=<s****************>, delay=1+01:11:31, xdelay=00:00:00, mailer=dovecot,
pri=4787366, relay=localhost, dsn=4.4.2, reply=75, stat=Deferred


######################*****##############
### DOVECOT Mailer specification ###
##################*****##################
Mdovecot, P=[IPC], F=zDFMPhnul59,
        S=EnvFromSMTP/HdrFromSMTP, R=EnvToSMTP/HdrFromSMTP,
        T=DNS/RFC822/X-Unix,
        A=FILE /var/run/dovecot/lmtp



dovecot -n
?????

# 2.3.11.3 (502c39af9): /usr/local/etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.11 (d71e0372)
doveconf: Warning: service auth { client_limit=100 } is lower than required
under max. load (300)
doveconf: Warning: service anvil { client_limit=100 } is lower than required
under max. load (203)
# OS: Darwin 15.6.0 x86_64  
# Hostname: ***************
doveconf: Error: t_readlink(/var/run/dovecot//dovecot.conf) failed: readlink()
failed: Permission denied
auth_mechanisms = cram-md5
auth_username_format = %Ln
base_dir = /var/run/dovecot/
default_client_limit = 100
default_internal_group = _dovecot
default_internal_user = _dovecot
default_login_user = _dovenull
hostname =*****************
lda_mailbox_autocreate = yes
mail_gid = 530
mail_home = /var/mail/%d/%n
mail_location = sdbox:~/dbox
mail_uid = 530
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character
vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy
include variables body enotify environment mailbox date index ihave duplicate
mime foreverypart extracttext
namespace inbox {
  inbox = yes
  location = 
  mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix = 
}
passdb {
  args = scheme=SSHA256 username_format=%u /usr/local/etc/dovecot/users
  driver = passwd-file
}
plugin {
  sieve = file:~/sieve;active=~/.dovecot.sieve
}
postmaster_address = postmaster
protocols = imap lmtp
service auth {
  unix_listener auth-userdb {
    group = mailusers
    mode = 0777
    user = _dovecot
  }

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20201210/c3d9c3ea/attachment-0001.html>

John Fawcett

2020-Dec-10 16:15 UTC

head link

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

On 10/12/2020 14:58, Steve Akerman wrote:> Good afternoon
>
> I have been using Dovecot with great success for several months now
> with one problem:
>
> I have received several messages (3 to date out of a much larger
> number) which cause Dovecot LMTP to drop the connection with sendmail
> after only receiving the first part of the message.
>
> Dovecot saves the first part to INBOX, and then drops the link with
> sendmail as it sees the rest of the data from sendmail as new (and
> invalid) commands
>
> Sendmail sees the delivery as unsuccessful and requeues the message,
> so the cycle continues until i kill the queue
>
> These messages are all Multipart MIME
>
> I have attached an extract from the log which shows the above sequence
>
> Finally, I have kept one such message from the sendmail queue (df and
> qf) should this be useful, but prefer not to post here as not sanitised?
>
> Any help in correcting my configuration would be appreciated.
>
> Thanks
>
> Steve
>
> <snip>
>Hi Steve

strange as it sounds, looks like your mta is sending the lmtp end of
message sequence (<CRLF>.<CRLF>)in the middle of an email.

You might be able to debug it in dovecot with lmtp_rawlog_dir setting
which will show the input and output dialog of the lmtp session.

John

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20201210/0ebf452c/attachment.html>

Steve Akerman

2020-Dec-11 14:09 UTC

head link

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

Good afternoon

Problem Solved!

After some very useful input from John Fawcett, I have identified that the
problem was not Dovecot, but the mailer used for Dovecot in Sendmail; it was
missing the F=X flag that double dots any single dots, which are rather common
in messages that were badly truncated to 75 line length by Apple Mail and
Outlook amongst others.

The correct Mailer spec for Dovecot LMTP is:

######################*****##############
### DOVECOT Mailer specification ###
##################*****##################
Mdovecot, P=[IPC], F=zDFMPXhnul59,
        S=EnvFromSMTP/HdrFromSMTP, R=EnvToSMTP/HdrFromSMTP,
        T=DNS/RFC822/X-Unix,
        A=FILE /var/run/dovecot/lmtp

which should be in a file called Dovecot inside sendmail cf/mailers and included
in the site mc file as

MAILER(`dovecot?)dnl

As this information is missing from the very good WIKI, could someone add it in
order to help others in the future?

Thanks

Steve

> On 10 Dec 2020, at 14:58, Steve Akerman <steve.akerman at
aboukir.com> wrote:
> 
> Good afternoon
> 
> I have been using Dovecot with great success for several months now with
one problem:
> 
> I have received several messages (3 to date out of a much larger number)
which cause Dovecot LMTP to drop the connection with sendmail after only
receiving the first part of the message.
> 
> Dovecot saves the first part to INBOX, and then drops the link with
sendmail as it sees the rest of the data from sendmail as new (and invalid)
commands
> 
> Sendmail sees the delivery as unsuccessful and requeues the message, so the
cycle continues until i kill the queue
> 
> These messages are all Multipart MIME
> 
> I have attached an extract from the log which shows the above sequence
> 
> Finally, I have kept one such message from the sendmail queue (df and qf)
should this be useful, but prefer not to post here as not sanitised
> 
> Any help in correcting my configuration would be appreciated.
> 
> Thanks
> 
> Steve
> 
> 
> MAIL LOG extract
> -------------------------
> 
> Dec  9 12:00:10 phone dovecot[179]: lmtp(20774): Connect from local
> Dec  9 12:00:10 phone sm-mta-rx[20764]: STARTTLS=client, relay=localhost,
version=TLSv1.3, verify=OK, cipher=TLS_AES_256_GCM_SHA384, bits=256/256
> Dec  9 12:00:10 phone dovecot[179]: lmtp(20775): Connect from local
> Dec  9 12:00:10 phone sm-mta-rx[20763]: STARTTLS=client, relay=localhost,
version=TLSv1.3, verify=OK, cipher=TLS_AES_256_GCM_SHA384, bits=256/256
> Dec  9 12:00:10 phone dovecot[179]:
lmtp(*********)<20775><8EieKDqu0F8nUQAA0J78UA>:
msgid=<39113a86-fdbb-4cea-b1c3-d225dff93328 at info.ameli.fr
<mailto:39113a86-fdbb-4cea-b1c3-d225dff93328 at info.ameli.fr>>: saved
mail to INBOX
> Dec  9 12:00:10 phone dovecot[179]: lmtp(20775): Disconnect from local: Too
many invalid commands. (state=READY)
> Dec  9 12:00:10 phone sm-mta-rx[20763]: STARTTLS: write error=syscall error
(-1), errno=32, get_error=error:00000000:lib(0):func(0):reason(0), retry=1,
ssl_err=5
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: SYSERR(root):
timeout writing message to localhost: Broken pipe
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   0: fl=0x0,
mode=20666: CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   1: fl=0x1,
mode=20666: CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   2: fl=0x1,
mode=20666: CHR: dev=30/1306024, ino=301, nlink=1, u/gid=0/0, size=0
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   3: fl=0x4002,
mode=100600: dev=1/2, ino=26089780, nlink=1, u/gid=0/23, size=2041
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   4: fl=0x0,
mode=20666: CHR: dev=30/1306024, ino=575, nlink=1, u/gid=0/0, size=0
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   5: fl=0x2,
mode=140666: SOCK localhost->[[UNIX: /var/run/mDNSResponder]]
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   6: fl=0x0,
mode=100640: dev=1/2, ino=25887976, nlink=1, u/gid=0/23, size=12288
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   7: fl=0x0,
mode=100640: dev=1/2, ino=25887976, nlink=1, u/gid=0/23, size=12288
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   8: fl=0x0,
mode=100600: dev=1/2, ino=26088246, nlink=1, u/gid=0/23, size=58024
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:   9: fl=0x6,
mode=140444: SOCK localhost->(Invalid argument)
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  10: fl=0x6,
mode=140444: SOCK localhost->(Invalid argument)
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  11: fl=0x0,
mode=100640: dev=1/2, ino=25768590, nlink=1, u/gid=0/23, size=12288
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:  12: fl=0x0,
mode=100640: dev=1/2, ino=25768590, nlink=1, u/gid=0/23, size=12288
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: MCI at 0x0: NULL
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803: MCI at
0x7fae2c814818:
flags=26404c<CACHED,ESMTP,8BITMIME,INMIME,ENHSTAT,PIPELINED,TLSACT>,
errno=32, herrno=0, exitstat=75, state=8, pid=0, maxsize=0, phase=client DATA
354, mailer=dovecot, status=4.4.2, rstatus=(null), host=localhost, lastuse=Wed
Dec  9 12:00:10 2020\n
> Dec  9 12:00:10 phone sm-mta-rx[20763]: 0B89mOON016803:
to=<s****************>, delay=1+01:11:31, xdelay=00:00:00, mailer=dovecot,
pri=4787366, relay=localhost, dsn=4.4.2, reply=75, stat=Deferred
> 
> 
> ######################*****##############
> ### DOVECOT Mailer specification ###
> ##################*****##################
> Mdovecot, P=[IPC], F=zDFMPhnul59,
>         S=EnvFromSMTP/HdrFromSMTP, R=EnvToSMTP/HdrFromSMTP,
>         T=DNS/RFC822/X-Unix,
>         A=FILE /var/run/dovecot/lmtp
> 
> 
> 
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20201211/7017ffb3/attachment-0001.html>

dovecot - Dec 2020 - Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received

Dovecot 2.3.11.3 LMTP dropping connection after first part of multipart message received