Panic: file smtp-client-connection.c: line 1212 (smtp_client_connection_established): assertion failed: (!conn->connect_succeeded)

Hativ hativ3 at gmail.com
Fri Oct 11 10:50:18 EEST 2019 

Hello,

after migrating from self-compiled Dovecot 2.3.3 to Dovecot 2.3.8 from
the repository (Ubuntu 18.04 LTS "Bionic" packages) I have issues with
the submission service. If I send an email, it will not be forwarded
and I get the following error message:

Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Panic: file smtp-client-connection.c:
line 1212 (smtp_client_connection_established): assertion failed:
(!conn->connect_succeeded)
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(+0xe7f7e) [0x7f64b1f76f7e] ->
/usr/lib/dovecot/libdovecot.so.0(+0xe8021) [0x7f64b1f77021] ->
/usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f64b1ecfaf4] ->
/usr/lib/dovecot/libdovecot.so.0(+0x50ec8) [0x7f64b1edfec8] ->
/usr/lib/dovecot/libdovecot.so.0(+0x51078) [0x7f64b1ee0078] ->
/usr/lib/dovecot/libdovecot.so.0(+0x541f4) [0x7f64b1ee31f4] ->
/usr/lib/dovecot/libdovecot.so.0(smtp_client_command_input_reply+0x1f8)
[0x7f64b1edb738] -> /usr/lib/dovecot/libdovecot.so.0(+0x54a93)
[0x7f64b1ee3a93] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x6f) [0x7f64b1f909af]
-> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13c)
[0x7f64b1f9237c] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4c)
[0x7f64b1f90abc] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7f64b1f90cd8] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
[0x7f64b1eff053] -> dovecot/submission [hativ at example.com
fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e GREETING](main+0x3d1) [0x55dcc748fec1] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f64b1abfb97] -> dovecot/submission [hativ at example.com fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e
GREETING](_start+0x2a) [0x55dcc749009a]

Does somebody has any idea? The problem has been taking me months, now
I want to finally update to the current version.

Full debug log:
Oct 11 09:29:00 srv2 dovecot: submission-login: Login: user=<
hativ at example.com>, method=PLAIN,
rip=fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e, lip=fec0:4f8:1c0c:8099::1,
mpid=15819, TLS, session=<XFnLeJ2U0rgqAoEMwMAIoDQqhHgB7k+O>
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Loading modules from directory:
/usr/lib/dovecot/modules
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib01_acl_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib10_quota_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib15_notify_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib20_mail_log_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib20_quota_clone_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Module loaded:
/usr/lib/dovecot/modules/lib20_replication_plugin.so
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Added userdb setting:
plugin/mail_crypt_private_password=<hidden>
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Added userdb setting:
plugin/mail_crypt_save_version=0
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Added userdb setting:
plugin/quota_rule=*:bytes=0
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Effective uid=998, gid=998,
home=/srv/mail/example.com/hativ
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Quota root: name= backend=count
args=
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Quota rule: root= mailbox=*
bytes=0 messages=0
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Quota grace: root= bytes=0 (10%)
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Namespace INBOX: type=private,
prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes
location=sdbox:~/
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: fs:
root=/srv/mail/example.com/hativ, index=, indexpvt=, control=, inbox=,
alt=
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: initializing backend with
data: vfile
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: acl username = 
hativ at example.com
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: owner = 1
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl vfile: Global ACLs disabled
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: Namespace Shared: type=shared,
prefix=Shared/%u/, sep=, inbox=no, hidden=no, list=children,
subscriptions=yes location=sdbox:%h/:INDEXPVT=~/shares/%u
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: shared: root=/var/run/dovecot,
index=, indexpvt=, control=, inbox=, alt=
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: initializing backend with
data: vfile
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: acl username = 
hativ at example.com
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl: owner = 0
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: acl vfile: Global ACLs disabled
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: quota: quota_over_flag check:
quota_over_script unset - skipping
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-server: conn
[fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e]:47314 [1]: Server accepted
connection (fd=7)
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-server: conn
[fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e]:47314 [1]: Connection created
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 [1]: Connection created
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 [1]: Looking up IP address
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 [1]: DNS lookup successful; got 2 IPs
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-server: conn
[fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e]:47314 [1]: Sent: 235 2.7.0
Logged in.
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 [1]: Connecting to 10.46.163.91:25
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Connecting
Oct 11 09:29:00 srv2 postfix/smtpd[15229]: connect from
srv2[10.46.163.91]
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Waiting for connect (fd=8)
to finish for max 0 msecs
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Client connected (fd=8)
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Connected to server (from
10.46.163.91:60230)
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Received greeting from
server: 220 mta2.example.com ESMTP
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Sending EHLO handshake
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command EHLO: Submitted with
priority
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command EHLO: Sent: EHLO
mda1-2.example.com
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command EHLO: Got reply
(1/1): 250 mta2.example.com PIPELINING SIZE 51200000 ETRN STARTTLS AUTH
DIGEST-MD5 CRAM-MD5 NTLM XCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT
LOGIN DESTADDR DESTPORT ENHANCEDSTATUSCODES 8BITMIME SMTPUTF8 (1
commands pending, 0 commands queued)
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Received handshake reply
Oct 11 09:29:00 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Received server capabilities
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Starting TLS
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command STARTTLS: Submitted
with priority
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command EHLO: Destroy (0
commands pending, 1 commands queued)
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command STARTTLS: Sent:
STARTTLS
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: command STARTTLS: Got reply
(1/1): 220 2.0.0 Ready to start TLS (1 commands pending, 0 commands
queued)
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Received STARTTLS reply: 220
2.0.0 Ready to start TLS
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: Starting SSL handshake
Oct 11 09:29:01 srv2 postfix/smtpd[15229]: Anonymous TLS connection
established from srv2[10.46.163.91]: TLSv1.3 with cipher
TLS_AES_256_GCM_SHA384 (256/256 bits)
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Debug: smtp-client: conn
mta2.example.com:25 (10.46.163.91:25) [1]: SSL handshake successful
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Panic: file smtp-client-connection.c:
line 1212 (smtp_client_connection_established): assertion failed:
(!conn->connect_succeeded)
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(+0xe7f7e) [0x7f64b1f76f7e] ->
/usr/lib/dovecot/libdovecot.so.0(+0xe8021) [0x7f64b1f77021] ->
/usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f64b1ecfaf4] ->
/usr/lib/dovecot/libdovecot.so.0(+0x50ec8) [0x7f64b1edfec8] ->
/usr/lib/dovecot/libdovecot.so.0(+0x51078) [0x7f64b1ee0078] ->
/usr/lib/dovecot/libdovecot.so.0(+0x541f4) [0x7f64b1ee31f4] ->
/usr/lib/dovecot/libdovecot.so.0(smtp_client_command_input_reply+0x1f8)
[0x7f64b1edb738] -> /usr/lib/dovecot/libdovecot.so.0(+0x54a93)
[0x7f64b1ee3a93] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x6f) [0x7f64b1f909af]
-> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13c)
[0x7f64b1f9237c] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4c)
[0x7f64b1f90abc] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7f64b1f90cd8] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
[0x7f64b1eff053] -> dovecot/submission [hativ at example.com
fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e GREETING](main+0x3d1) [0x55dcc748fec1] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f64b1abfb97] -> dovecot/submission [hativ at example.com fec0:810c:c0c0:8a0:342a:8478:1ee:4f8e
GREETING](_start+0x2a) [0x55dcc749009a]
Oct 11 09:29:01 srv2 postfix/smtpd[15229]: lost connection after
STARTTLS from srv2[10.46.163.91]
Oct 11 09:29:01 srv2 postfix/smtpd[15229]: disconnect from
srv2[10.46.163.91] ehlo=1 starttls=1 commands=2
Oct 11 09:29:01 srv2 dovecot: submission(hativ at example.com)<15819><XFnL
eJ2U0rgqAoEMwMAIoDQqhHgB7k+O>: Fatal: master: service(submission):
child 15819 killed with signal 6 (core dumped)

Best regards

Hativ
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20191011/5b42a45f/attachment-0001.html>

More information about the dovecot mailing list