TCPConnection - TLS/SSL handshake failed. (...), Error code: 1, Message: stream trunca
Posted: 2019-08-20 07:01
Hi all,
recently I got complaints about some mailboxes (all get fetched from external pop3 accounts) not receiving mails for hours (randomly for about 3 or 4, sometimes even 8 hours).
After checking the logs I found that endeed some of the accounts fail in SSL/TLS handshaking and so don't connect and don't fetch new mails from pop3.
The strange thing is, if I trigger by the "Download now" button within one of the external accounts the immediate fetch works. As well the first try after a hms restart always seems to work. All of the accounts (the working and the ones with the handshake error fetch from the same server (XX.XXX.XX.X) with the same settings except the last two lines in the log showing YYY.YYY.YY.YYY, which is another server. All accounts are set up identically (fetch every 2 minutes, use SSL/TLS, Anti-SPAM and Anti-Virus active, delete after 31 days), at least as I tried to double checked them all carefully.
Disabling all pop3 fetches one by one and renenabling them did work for the effected ones just one time. After that, the handshakes starts failing again while the other accounts which already worked before stay working.
In total there are about 20 accounts using pop3 collect from which I think nearly 25-50% do have the handshake problem.
What I already tried:
- updating to the newest (I know "non porduction") build (HMS 5.7.0-B2484 as it already was on 5.7.0-2469) --> no difference
- disabling all pop3 accounts one by one and renenabling --> works just after enabling one time
- fetching manually by triggering "Download now" button --> works - as far as I can tell allways
- deleting one of the affected external pop3 accounts and creating it new --> works one time but fetches again all mails not having alrady been deleted on pop3 server and so messes up the users mailbox - don't like to try that again
- enabling and disabling of "TLS v1.3" --> no difference
- enabling and disabling of "Verify remote server SSL/TLS certificate" --> no difference
- tried to somehow install the certifcate of the pop3 server locally on hms --> no difference
Does anyone by any chance have a clue what this can be and how to fix it?
Many thanks in advance for any hint or help!
recently I got complaints about some mailboxes (all get fetched from external pop3 accounts) not receiving mails for hours (randomly for about 3 or 4, sometimes even 8 hours).
After checking the logs I found that endeed some of the accounts fail in SSL/TLS handshaking and so don't connect and don't fetch new mails from pop3.
The strange thing is, if I trigger by the "Download now" button within one of the external accounts the immediate fetch works. As well the first try after a hms restart always seems to work. All of the accounts (the working and the ones with the handshake error fetch from the same server (XX.XXX.XX.X) with the same settings except the last two lines in the log showing YYY.YYY.YY.YYY, which is another server. All accounts are set up identically (fetch every 2 minutes, use SSL/TLS, Anti-SPAM and Anti-Virus active, delete after 31 days), at least as I tried to double checked them all carefully.
Disabling all pop3 fetches one by one and renenabling them did work for the effected ones just one time. After that, the handshakes starts failing again while the other accounts which already worked before stay working.
In total there are about 20 accounts using pop3 collect from which I think nearly 25-50% do have the handshake problem.
Code: Select all
"DEBUG" 130648 "2019-08-20 06:19:13.646" "TCP connection started for session 589"
"DEBUG" 130648 "2019-08-20 06:19:13.647" "Performing SSL/TLS handshake for session 589. Verify certificate: True, Expected remote host name: pop.XXX.de"
"DEBUG" 130648 "2019-08-20 06:19:13.648" "TCP connection started for session 590"
"DEBUG" 108256 "2019-08-20 06:19:13.648" "Certificate verification succeeded for session 578."
"DEBUG" 130648 "2019-08-20 06:19:13.649" "Performing SSL/TLS handshake for session 590. Verify certificate: True, Expected remote host name: pop.XXX.de"
"DEBUG" 67736 "2019-08-20 06:19:13.649" "Certificate verification succeeded for session 579."
"DEBUG" 120292 "2019-08-20 06:19:13.650" "TCP connection started for session 588"
"DEBUG" 92100 "2019-08-20 06:19:13.651" "Certificate verification succeeded for session 580."
"DEBUG" 120292 "2019-08-20 06:19:13.652" "Performing SSL/TLS handshake for session 588. Verify certificate: True, Expected remote host name: pop.YYY.de"
"TCPIP" 19560 "2019-08-20 06:19:13.653" "TCPConnection - TLS/SSL handshake failed. Session Id: 589, Remote IP: XX.XXX.XX.X, Error code: 1, Message: stream truncated"
"DEBUG" 19560 "2019-08-20 06:19:13.654" "Ending session 589"
"DEBUG" 58612 "2019-08-20 06:19:13.655" "Completed retrieval of messages from external account."
"TCPIP" 19560 "2019-08-20 06:19:13.655" "TCPConnection - TLS/SSL handshake failed. Session Id: 590, Remote IP: XX.XXX.XX.X, Error code: 1, Message: stream truncated"
"DEBUG" 19560 "2019-08-20 06:19:13.657" "Ending session 590"
"TCPIP" 67736 "2019-08-20 06:19:13.657" "TCPConnection - TLS/SSL handshake completed. Session Id: 577, Remote IP: XX.XXX.XX.X, Version: TLSv1.2, Cipher: AES128-GCM-SHA256, Bits: 128"
"DEBUG" 57144 "2019-08-20 06:19:13.657" "Completed retrieval of messages from external account."
"DEBUG" 92100 "2019-08-20 06:19:13.660" "Certificate verification succeeded for session 584."
"TCPIP" 67736 "2019-08-20 06:19:13.665" "TCPConnection - TLS/SSL handshake completed. Session Id: 578, Remote IP: XX.XXX.XX.X, Version: TLSv1.2, Cipher: AES128-GCM-SHA256, Bits: 128"
"TCPIP" 67736 "2019-08-20 06:19:13.669" "TCPConnection - TLS/SSL handshake completed. Session Id: 579, Remote IP: XX.XXX.XX.X, Version: TLSv1.2, Cipher: AES128-GCM-SHA256, Bits: 128"
"TCPIP" 67736 "2019-08-20 06:19:13.671" "TCPConnection - TLS/SSL handshake completed. Session Id: 580, Remote IP: XX.XXX.XX.X, Version: TLSv1.2, Cipher: AES128-GCM-SHA256, Bits: 128"
"DEBUG" 67736 "2019-08-20 06:19:13.678" "Certificate verification succeeded for session 588."
"TCPIP" 92100 "2019-08-20 06:19:13.693" "TCPConnection - TLS/SSL handshake completed. Session Id: 584, Remote IP: YYY.YYY.YY.YYY, Version: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256, Bits: 128"
"TCPIP" 92100 "2019-08-20 06:19:13.710" "TCPConnection - TLS/SSL handshake completed. Session Id: 588, Remote IP: YYY.YYY.YY.YYY, Version: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256, Bits: 128"
- updating to the newest (I know "non porduction") build (HMS 5.7.0-B2484 as it already was on 5.7.0-2469) --> no difference
- disabling all pop3 accounts one by one and renenabling --> works just after enabling one time
- fetching manually by triggering "Download now" button --> works - as far as I can tell allways
- deleting one of the affected external pop3 accounts and creating it new --> works one time but fetches again all mails not having alrady been deleted on pop3 server and so messes up the users mailbox - don't like to try that again

- enabling and disabling of "TLS v1.3" --> no difference
- enabling and disabling of "Verify remote server SSL/TLS certificate" --> no difference
- tried to somehow install the certifcate of the pop3 server locally on hms --> no difference
Does anyone by any chance have a clue what this can be and how to fix it?
Many thanks in advance for any hint or help!