submission server fails to relay messages

Mon Sep 13 20:05:56 EEST 2021

Hi guys!

I'm using dovecot submission server for clients to send emails and relay
them to postfix. Everything works fine unless a client tries to send large
(40Mbs) messages. No big deal one can say just set "message_size_limit =
314572800" in postfix and it should just work, but no, it does not, client
gets "552 5.2.3 Message size exceeds administrative limit.". I've increased
verbosity for smtpd process and get this logs for a failed attempt

Sep 12 13:43:21 mx10 postfix/smtpd[73602]: connection established
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: master_notify: status 0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: name_mask: resource
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: name_mask: software
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: watchdog_start: 0x563f80b341b0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left   5 for
> 0x7fdef6cf4700 0x563f80b393d0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left   5 for
> 0x7fdef6cf4700 0x563f80b1ee10
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left 100 for
> 0x7fdef6d56b20 0x0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left 1000 for
> 0x7fdef6cf4720 0x563f80b1ee10
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left 1000 for
> 0x7fdef6cf4720 0x563f80b393d0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: select_delay 0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: timer
> 0x7fdef6cf4700 0x563f80b393d0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: rewrite stream disconnect
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_disable_readwrite: fd 20
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_cancel_timer:
> 0x7fdef6cf4700 0x563f80b393d0 -1
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_cancel_timer:
> 0x7fdef6cf4720 0x563f80b393d0 985
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: timer
> 0x7fdef6cf4700 0x563f80b1ee10
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: proxymap stream disconnect
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_disable_readwrite: fd 10
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_cancel_timer:
> 0x7fdef6cf4700 0x563f80b1ee10 -1
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_cancel_timer:
> 0x7fdef6cf4720 0x563f80b1ee10 985
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: watchdog_stop: 0x563f80b341b0
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: watchdog_start: 0x563f80b341b0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: connect from
> localhost[127.0.0.1]
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: time left  85 for
> 0x7fdef6d56b20 0x0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: localhost: no
> match
> Sep 12 13:43:21 mx10 postfix/smtpd[73615]: event_loop: select_delay 85
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: 127.0.0.1:
> no match
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: localhost: no
> match
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: 127.0.0.1:
> no match
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: smtp_stream_setup: maxtime=300
> enable_deadline=0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_hostname:
> smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.0/8
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_hostaddr:
> smtpd_client_event_limit_exceptions: 127.0.0.1 ~? 127.0.0.0/8
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 220
> mx10 ESMTP Postfix (Debian/GNU)
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: watchdog_pat: 0x5609a03c01b0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: vstream_fflush_some: fd 10
> flush 47
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: vstream_buf_get_ready: fd 10
> got 21
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: < localhost[127.0.0.1]: EHLO
> mx10
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: localhost: no
> match
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: match_list_match: 127.0.0.1:
> no match
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 250-mx10
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]:
> 250-PIPELINING
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]:
> 250-SIZE 314572800
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 250-VRFY
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 250-ETRN
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]:
> 250-ENHANCEDSTATUSCODES
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]:
> 250-8BITMIME
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 250-DSN
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 250
> CHUNKING
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: watchdog_pat: 0x5609a03c01b0
> Sep 12 13:43:21 mx10 postfix/smtpd[73602]: vstream_fflush_some: fd 10
> flush 138
> Sep 12 13:43:22 mx10 postfix/smtpd[73602]: vstream_buf_get_ready: fd 10
> got 6
> Sep 12 13:43:22 mx10 postfix/smtpd[73602]: < localhost[127.0.0.1]: QUIT
> Sep 12 13:43:22 mx10 postfix/smtpd[73602]: > localhost[127.0.0.1]: 221
> 2.0.0 Bye
>

looks like submission server just quits

if I configure imap client /Thunderbird to connect directly to postfix
everything works just fine.

doveconf -n output is attached just in case
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20210913/c26011a7/attachment-0001.html>
-------------- next part --------------
# 2.3.16 (7e2e900c1a): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.16 (09c29328)
# OS: Linux 4.19.0-13-amd64 x86_64 Debian 10.10 
# Hostname: mx10
debug_log_path = /var/log/dovecot.debug
default_vsz_limit = 8 G
disable_plaintext_auth = no
first_valid_gid = 500
haproxy_trusted_networks = 127.0.0.1
info_log_path = /var/log/dovecot.info
listen = 127.0.0.1
log_path = /var/log/dovecot.log
mail_gid = 500
mail_home = /storage/vmail/maildir/%d/%n
mail_location = maildir:~/Maildir:LAYOUT=fs
mail_plugins = acl zlib notify
mail_shared_explicit_inbox = yes
mail_uid = 500
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 {
    auto = subscribe
    special_use = \Drafts
  }
  mailbox Junk {
    auto = subscribe
    special_use = \Junk
  }
  mailbox Sent {
    auto = subscribe
    special_use = \Sent
  }
  mailbox Trash {
    auto = subscribe
    special_use = \Trash
  }
  prefix = 
  separator = /
}
namespace shared {
  list = children
  location = maildir:%%h/Maildir:LAYOUT=fs
  prefix = shared/%%u/
  separator = /
  subscriptions = no
  type = shared
}
passdb {
  args = /etc/dovecot/vmail/postfixadmin.conf
  driver = sql
}
passdb {
  args = /etc/dovecot/vmail/master.conf
  driver = sql
}
plugin {
  acl = vfile
  acl_shared_dict = file:/storage/vmail/maildir/shared-mailboxes.db
  sieve = file:~/sieve;active=~/active.sieve
  sieve_max_redirects = 0
  zlib_save = gz
  zlib_save_level = 6
}
protocols = " imap lmtp sieve submission"
service auth {
  unix_listener auth-userdb {
    mode = 0777
  }
}
service imap-login {
  inet_listener imap-haproxy {
    haproxy = yes
    port = 144
  }
  inet_listener imap {
    haproxy = no
    port = 143
  }
}
service lmtp {
  inet_listener lmtp {
    port = 125
  }
}
service submission-login {
  inet_listener submission-haproxy {
    haproxy = yes
    port = 588
  }
  inet_listener submission {
    haproxy = no
    port = 587
  }
}
ssl = no
submission_relay_host = 127.0.0.1
userdb {
  args = /etc/dovecot/vmail/postfixadmin.conf
  driver = sql
}
protocol lmtp {
  mail_plugins = acl zlib notify sieve
}
protocol imap {
  mail_max_userip_connections = 50
  mail_plugins = acl zlib notify imap_acl
}