Potential issue with lmtp_rawlog_dir when using TLS

[John Fawcett]

Hi

not sure why this happens, but looks like lmtp_rawlog_dir blocks the
successful negotiation of an lmtp starttls connection.

Reproducible with openssl s_client.  Two runs with only difference the
presence of lmtp_rawlog_dir setting in dovecot config.

Failed connection with lmtp_rawlog_dir

Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Connect from ::1
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL:
where=0x10, ret=1: before SSL initialization
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL:
where=0x2001, ret=1: before SSL initialization
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL:
where=0x2002, ret=-1: error
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL error:
SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong
version number
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Error:
lmtp-server: conn [::1]:53876 [2]: SSL handshake failed: SSL_accept()
failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Debug: SSL error:
SSL_accept() syscall failed: Invalid argument
Dec 10 21:01:31 server03 dovecot[41002]: lmtp(41021): Disconnect from
::1: SSL Initialization failed (state=READY)


Successful connection without lmtp_rawlog_dir

Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Connect from ::1
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x10, ret=1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: before SSL initialization
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug:
SSL_get_servername() failed
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS read client hello
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write server hello
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write change cipher spec
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: TLSv1.3 write encrypted extensions
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write certificate
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: TLSv1.3 write server certificate verify
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write finished
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=-1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: TLSv1.3 early data
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS read finished
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x20, ret=1: SSLv3/TLS write session ticket
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write session ticket
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2001, ret=1: SSLv3/TLS write session ticket
Dec 10 20:59:07 server03 dovecot[40970]: lmtp(40988): Debug: SSL:
where=0x2002, ret=1: SSL negotiation finished successfully

John