Thanks for your quick reply Thomas, ConTimeOutDebug was already switched on. Now I additionally set connections logging to diagnostic. Then I sent 3 identical mails with only one word of text from gmx.de for testing, 1 got through immediately, the other 2 timed out. The timeout appears during SSL renegotiation. Here is one working and one failing example:
--------------- Working example ------------------ Dec 16 13:33:39 localhost assp.pl[115465]: [Worker_1] Worker_1 wakes up Dec 16 13:33:39 localhost assp.pl[115465]: [Worker_1] Info: Worker_1 got connection from MainThread Dec 16 13:33:39 localhost assp.pl[115465]: [Worker_1] Info: try to connect to server at 127.0.0.1:125 Dec 16 13:33:39 localhost assp.pl[115465]: [Worker_1] Info: connected to server at 127.0.0.1:125 Dec 16 13:33:39 localhost assp.pl[115465]: [Worker_1] Connected: session:5620A0F072B8 212.227.15.15:50033 > 192.168.12.242:25 > 127.0.0.1:46818 > 127.0.0.1:125 , 771-772 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] 212.227.15.15 Disabled SMTP AUTH for External IPs Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] 212.227.15.15 info: injected '250-STARTTLS' offer in to EHLO reply Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] 212.227.15.15 info: send '250-STARTTLS' - injected for 127.0.0.1 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] 212.227.15.15 info: removed '250-STARTTLS' - it was already injected Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] 212.227.15.15 info: got STARTTLS request from 212.227.15.15 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1030: starting sslifying Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> 1 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1125: handshake done, socket ready Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] [TLS-in] 212.227.15.15 info: started TLS-SSL session for client 212.227.15.15 - using TLSv1_2 , ECDHE-RSA-AES128-GCM-SHA256 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:757: ssl handshake not started Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:802: not using SNI because hostname is unknown Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3093: get_session(127.0.0.1:125) -> none Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:850: set socket to non-blocking to enforce timeout=5 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> 1 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:921: ssl handshake done Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] info: started TLS-SSL session for server 127.0.0.1 - using TLSv1_3 , TLS_AES_256_GCM_SHA384 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2970: callback session new <127.0.0.1:125> 140333578219488 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3040: add_session(127.0.0.1:125,140333578219488) Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] info: ssl-read - renegotiation in progress - SSL_WANT_READ Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] info: ssl-read renegotiation finished - recovered from - SSL_WANT_READ Dec 16 13:33:40 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> info: found message size announcement: 2.28 kByte Dec 16 13:33:40 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> Message-Score: added -10 (tlsValencePB) for SSL-TLS-connection-OK, total score for this message is now -10 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for 'gmx.de' type 'NS' to nameserver 192.168.12.241 ID 59457 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] Info: got DNS DATA answer from nameserver 192.168.12.241 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS DATA answer from nameserver 192.168.12.241 ID 59457 Dec 16 13:33:40 localhost assp.pl[115465]: [Worker_1] kulm...@capricomp.de matches kulm...@capricomp.de in LocalAddresses_Flat Dec 16 13:33:40 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: allocated 71.80 kByte memory to process this mail Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de DKIM-Signature found Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: enhanced Originated IP detection ignored IP's: 212.227.15.15 (connected IP) , 172.19.170.92 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: enhanced Originated IP detection found IP's: 87.139.24.139 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: detected IP's on the mail routing way: 87.139.24.139 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: detected source IP: 87.139.24.139 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: found known good HELO 'mout.gmx.net' - weight is -2 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Message-Score: added -40 for KnownGoodHelo, total score for this message is now -50 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] kulm...@capricomp.de matches kulm...@capricomp.de in LocalAddresses_Flat Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Message-Score: added -3 for 212.227.15.0 in griplist (0.07), total score for this message is now -53 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for 'badeba3b8450._domainkey.gmx.net' type 'TXT' to nameserver 192.168.12.241 ID 41268 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got DNS DATA answer from nameserver 192.168.12.241 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS DATA answer from nameserver 192.168.12.241 ID 41268 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for '_policy._domainkey.gmx.de' type 'TXT' to nameserver 192.168.12.241 ID 26059 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS NON-DATA answer 'NXDOMAIN' from nameserver 192.168.12.241 ID 26059 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for '_domainkey.gmx.de' type 'TXT' to nameserver 192.168.12.241 ID 3224 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS NON-DATA answer 'NOERROR' from nameserver 192.168.12.241 ID 3224 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de [scoring] DKIM signature verified-OK - header-passed - identity is: @gmx.net - sender policy is: neutral - author policy is: neutral Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for '_dmarc.gmx.de' type 'TXT' to nameserver 192.168.12.241 ID 12513 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS NON-DATA answer 'NXDOMAIN' from nameserver 192.168.12.241 ID 12513 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de strictspf Regex: strictSPFRe '@gmx.de' Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de blockspf Regex: blockstrictSPFRe '@gmx.de' Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Message-Score: added -10 (spfpValencePB) for SPF pass, total score for this message is now -63 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: sent DNS query for '15.15.227.212.sa.senderbase.org' type 'TXT' to nameserver 192.168.12.241 ID 63199 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got DNS DATA answer from nameserver 192.168.12.241 Dec 16 13:33:41 localhost assp.pl[115465]: [Worker_1] Info: got valid DNS DATA answer from nameserver 192.168.12.241 ID 63199 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Message-Score: added -10 for Home IP-Country Bonus DE (1&1 INTERNET AG), total score for this message is now -73 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Message-Score: added -15 (pbwValencePB) for In Penalty White Box, total score for this message is now -88 Dec 16 13:33:41 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: check IP's on mail route for IP-blocking Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] Info: word stemming engine detected no language in mail Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de HMM-Check has given less than 6 results - using monitoring mode only Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de HMM Check [monitoring] - Prob: 0.00000 => ham - answer/query relation: 27% of 11 Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de Bayesian Check [scoring] - Prob: 0.00000 => ham - answer/query relation: 64% of 14 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] Warning: image processing is switched on. Extensive calls to image processing may lead in to a large performance penalty and/or stucking workers! Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] [Plugin] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de ASSP_OCR: Plugin(2.23) successful called for runlevel 'complete mail'! Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] VirusTotal uses direct HTTP connection Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de [Plugin] calling plugin ASSP_AFC Dec 16 13:33:42 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de ClamAV: scanned 141 bytes in message - OK Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2945: new ctx 140333607285184 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:732: socket not yet connected Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:734: socket connected Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:757: ssl handshake not started Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:799: using SNI with hostname www.virustotal.com Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:834: request OCSP stapling Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:850: set socket to non-blocking to enforce timeout=10 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> -1 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:876: ssl handshake in progress Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:886: waiting for fd to become ready: SSL wants a read first Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:906: socket ready, retrying connect Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2799: ok=1 [2] /C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2799: ok=1 [1] /C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=RapidSSL RSA CA 2018 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2799: ok=1 [0] /C=US/O=DigiCert Inc/OU=www.digicert.com/CN=RapidSSL RSA CA 2018/CN=*.virustotal.com Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1798: scheme=www cert=140333562491792 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1808: identity=www.virustotal.com cn=*.virustotal.com alt=2 *.virustotal.com 2 virustotal.com Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2846: did not get stapled OCSP response Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> 1 Dec 16 13:33:42 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:921: ssl handshake done Dec 16 13:33:43 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2994: free ctx 140333607285184 open=140333583501168 140333607285184 140333562810784 Dec 16 13:33:43 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2998: free ctx 140333607285184 callback Dec 16 13:33:43 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3005: OK free ctx 140333607285184 Dec 16 13:33:43 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de VirusTotal: scan finished - OK Dec 16 13:33:43 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de [Plugin] calling plugin ASSP_DCC Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: received all data - all data moved to send queue (7) Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] [MessageOK] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de message ok [Von GMX an ASSP] Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] [MessageOK] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: all DATA written to server - sent [CR][LF].[CR][LF] Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de finished message - received DATA size: 2.45 kByte - sent DATA size: 3.61 kByte Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de disconnected: session:5620A0F072B8 212.227.15.15 - command list was 'EHLO,STARTTLS,EHLO,MAIL FROM,RCPT TO,DATA,QUIT' - used 51 SocketCalls - processing time 7 seconds - damped 0 seconds Dec 16 13:33:47 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de info: scanning stored file /opt/assp/notspam/4635.eml for virus ( forced by ClamAVLogScan and/or FileLogScan ) Dec 16 13:33:48 localhost assp.pl[115465]: m1-99620-04635 [Worker_1] [TLS-in] [TLS-out] 212.227.15.15 <dirk.kulm...@gmx.de> to: kulm...@capricomp.de ClamAV: scanned 2510 bytes in file /opt/assp/notspam/4635.eml - OK Dec 16 13:33:48 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2976: callback session remove 140333578219488 Dec 16 13:33:48 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3066: del_session(undef,140333578219488) -> 1 Dec 16 13:33:48 localhost assp.pl[115465]: [Worker_1] Worker_1 will sleep now --------------- end working example ------------------ --------------- timeout example ------------------ Dec 16 13:47:47 localhost assp.pl[115465]: [Worker_3] Worker_3 wakes up Dec 16 13:47:47 localhost assp.pl[115465]: [Worker_3] Info: Worker_3 got connection from MainThread Dec 16 13:47:47 localhost assp.pl[115465]: [Worker_3] IP 212.227.17.20 matches debugIP - with 212.227.17.20/32 Dec 16 13:47:47 localhost assp.pl[115465]: [Worker_3] Info: try to connect to server at 127.0.0.1:125 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] Info: connected to server at 127.0.0.1:125 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] Connected: session:7FA1E043EC18 212.227.17.20:36379 > 192.168.12.242:25 > 127.0.0.1:46844 > 127.0.0.1:125 , 778-779 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] 212.227.17.20 Disabled SMTP AUTH for External IPs Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] Info: sent DNS query for '212.227.17.20' type 'PTR' to nameserver 192.168.12.241 ID 10421 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] Info: got DNS DATA answer from nameserver 192.168.12.241 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] Info: got valid DNS DATA answer from nameserver 192.168.12.241 ID 10421 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] 212.227.17.20 info: injected '250-STARTTLS' offer in to EHLO reply Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] 212.227.17.20 info: send '250-STARTTLS' - injected for 127.0.0.1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] 212.227.17.20 info: removed '250-STARTTLS' - it was already injected Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] 212.227.17.20 info: got STARTTLS request from 212.227.17.20 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1030: starting sslifying Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> 1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1125: handshake done, socket ready Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] [TLS-in] 212.227.17.20 info: started TLS-SSL session for client 212.227.17.20 - using TLSv1_3 , TLS_AES_256_GCM_SHA384 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:757: ssl handshake not started Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:802: not using SNI because hostname is unknown Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:3093: get_session(127.0.0.1:125) -> none Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:850: set socket to non-blocking to enforce timeout=5 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> -1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:876: ssl handshake in progress Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:886: waiting for fd to become ready: SSL wants a read first Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:906: socket ready, retrying connect Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> 1 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:921: ssl handshake done Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] [TLS-in] [TLS-out] info: started TLS-SSL session for server 127.0.0.1 - using TLSv1_3 , TLS_AES_256_GCM_SHA384 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:2970: callback session new <127.0.0.1:125> 140333266417424 Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] SSL-DEBUG: .../IO/Socket/SSL.pm:3040: add_session(127.0.0.1:125,140333266417424) Dec 16 13:47:48 localhost assp.pl[115465]: [Worker_3] [TLS-in] [TLS-out] info: ssl-read - renegotiation in progress - SSL_WANT_READ Dec 16 13:49:48 localhost assp.pl[115465]: [Worker_3] [TLS-in] [TLS-out] 212.227.17.20 info: no (more) data readable from 212.227.17.20 (connection closed by peer) - last command was 'EHLO' Dec 16 13:49:48 localhost assp.pl[115465]: [Worker_3] [TLS-in] [TLS-out] 212.227.17.20 disconnected: session:7FA1E043EC18 212.227.17.20 - command list was 'EHLO,STARTTLS,EHLO' - used 4 SocketCalls - processing time 120 seconds - damped 0 seconds --------------- end timeout example ------------------ Von: Thomas Eckardt <thomas.ecka...@thockar.com> Gesendet: Montag, 16. Dezember 2019 13:01 An: ASSP development mailing list <assp-test@lists.sourceforge.net> Betreff: Re: [Assp-test] TLS connections getting stuck enable 'ConTimeOutDebug' - the debug logs will show where the communication stucks Thomas Von: "Dirk Kulmsee" <d.kulm...@netgroup.de <mailto:d.kulm...@netgroup.de> > An: "'ASSP development mailing list'" <assp-test@lists.sourceforge.net <mailto:assp-test@lists.sourceforge.net> > Datum: 16.12.2019 12:43 Betreff: [Assp-test] TLS connections getting stuck _____ Hi all, i am currently using ASSP 2.6.4 19341 on Debian Linux, Perl 5.28 For some weeks now I have the problem that many TLS connections time out so mails are not received or are received after retries with huge delays up to several days. This happens with several different servers (e.g. from gmx.net, t-online.de) but it does not always happen. Most mail flows smoothly. I am using an official SSL certificate (Digicert wildcard), SSL_version and SSL_cipher_list are set to default. ASSP forwards mail to a Postfix on the same machine, port 125. Here are some log lines: Dec 16 11:54:32 localhost assp.pl[115465]: [Worker_1] Worker_1 wakes up Dec 16 11:54:32 localhost assp.pl[115465]: [Worker_1] Info: Worker_1 got connection from MainThread Dec 16 11:54:32 localhost assp.pl[115465]: [Worker_1] Connected: session:7FA1F68F3B30 212.18.1.53:33523 > 192.168.12.242:25 > 127.0.0.1:125 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] 212.18.1.53 Disabled SMTP AUTH for External IPs Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] 212.18.1.53 info: got STARTTLS request from 212.18.1.53 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1030: starting sslifying Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> -1 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1077: Net::SSLeay::accept -> 1 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1125: handshake done, socket ready Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:1578: start handshake Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:757: ssl handshake not started Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:802: not using SNI because hostname is unknown Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3093: get_session(127.0.0.1:125) -> none Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:850: set socket to non-blocking to enforce timeout=5 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:863: call Net::SSLeay::connect Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:866: done Net::SSLeay::connect -> 1 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:921: ssl handshake done Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:2970: callback session new <127.0.0.1:125> 140333579019952 Dec 16 11:54:33 localhost assp.pl[115465]: [Worker_1] SSL-DEBUG: .../IO/Socket/SSL.pm:3040: add_session(127.0.0.1:125,140333579019952) Dec 16 11:57:44 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] 212.18.1.53 TLS-Connection idle for 180 secs - timeout Dec 16 11:57:44 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] 212.18.1.53 [SMTP Status] 451 Connection timeout, try later Dec 16 11:57:44 localhost assp.pl[115465]: [Worker_1] [TLS-in] [TLS-out] 212.18.1.53 disconnected: session:7FA1F68F3B30 212.18.1.53 - processing time 0 seconds Dec 16 11:57:44 localhost assp.pl[115465]: [Worker_1] Worker_1 will sleep now The IP mentioned here ends up in SSL-failed-cache. Any ideas where to look or what to change? Best regards Dirk_______________________________________________ Assp-test mailing list Assp-test@lists.sourceforge.net <mailto:Assp-test@lists.sourceforge.net> <https://lists.sourceforge.net/lists/listinfo/assp-test> https://lists.sourceforge.net/lists/listinfo/assp-test DISCLAIMER: ******************************************************* This email and any files transmitted with it may be confidential, legally privileged and protected in law and are intended solely for the use of the individual to whom it is addressed. This email was multiple times scanned for viruses. There should be no known virus in this email! *******************************************************
_______________________________________________ Assp-test mailing list Assp-test@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/assp-test
