Thomas, just wanted to say "Thanks" for all that you do on the ASSP project. I was hopeful that this solution would fix the issue, but unfortunately it doesn't seem to. I've been running the new version, b14121 since a few hours after it came out. But I am still getting the SSL handshake failures from Amazon's mailservers. I'll provide more debug logs and maybe it'll be enough to find out what is the exact problem.
One more thing, with b14121, I actually had ASSP lockup four times in a span of a few hours, with high CPU load, apparently caused by stuck workers. That's something that has never happened before with ASSP. The stuck workers reported being on "PTROK" as the last command. It also happened with debugging off as well, so it wasn't just that. I did figure out the debug levels, since level 0 (no Debug) was first, I assumed that the levels would step up from there, in order, with Level 3 as the highest. But initially I was confused from the description since I've also seen things that start with level 1 as highest priority and descend from there. Below is the full debug (Level 3) log from a problem connection, from the beginning and down to where the SSL handshake error is given. After that it seems that the connection switches to plain-text SMTP and proceeds to successfully transfer the email. Note, I do not have any IPs listed in acceptAllMail or noTLSIP, much less these specific problems addresses, so I am not sure about the repeated lines saying MatchIP for the IP address. Perhaps it just means that it has checked the IP against that list? -C running ASSP version: 2.4.2(14121) May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noMaxSMTPSessions >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noProcessingIPs >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - whiteListedIPs >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noDelay >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - ispip >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - acceptAllMail >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noBlockingIPs >May-01-14 20:42:26 [Worker_1] <try to connect to server at 66.135.57.44:1025 >May-01-14 20:42:26 [Worker_1] <connected to server IO::Socket::INET=GLOB(0xdf79ca8) at 66.135.57.44:1025 >May-01-14 20:42:26 [Worker_1] <addfh >May-01-14 20:42:26 [Worker_1] <addfh >May-01-14 20:42:26 [Worker_1] <Connected: SID=F567A10 IO::Socket::INET=GLOB(0xf567a10) -- IO::Socket::INET=GLOB(0xdf79ca8) >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - acceptAllMail >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - acceptAllMail >May-01-14 20:42:26 [Worker_1] <TimeZoneDiff: -25200 seconds to GMT >May-01-14 20:42:26 [Worker_1] <* connect SID=F567A10 ip=54.240.13.36 relay=<0> * >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noLog >May-01-14 20:42:26 [Worker_1] <ThreadGetNewCon >May-01-14 20:42:26 [Worker_1] <rh: 2 - read: 1 - wait: 0.002 >May-01-14 20:42:26 [Worker_1] <wh: 2 - write: 2 - wait: 0.002 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xdf79ca8) l= >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l= >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - read OK >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - process read >May-01-14 20:42:26 [Worker_1] <doing line <220-spiffy.unpatented.com ESMTP Exim 4.82 #2 Thu, 01 May 2014 20:42:26 -0700 [CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 220-spiffy.unpatented.com ESMTP Exim 4.82 #2 Thu, 01 May 2014 20:42:26 -0700 [CR][LF] >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=79 >May-01-14 20:42:26 [Worker_1] <doing line <220-We do not authorize the use of this system to transport unsolicited, [CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 220-We do not authorize the use of this system to transport unsolicited, [CR][LF] >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=75 >May-01-14 20:42:26 [Worker_1] <doing line <220 and/or bulk e-mail.[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 220 and/or bulk e-mail.[CR][LF] >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xdf79ca8) l= >May-01-14 20:42:26 [Worker_1] <noop to server 1 >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=25 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xdf79ca8) l=0 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=179 >May-01-14 20:42:26 [Worker_1] <wrote: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 (179) >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - read OK >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - process read >May-01-14 20:42:26 [Worker_1] <doing line <EHLO a13-36.smtp-out.amazonses.com[CR][LF] > >May-01-14 20:42:26 [Worker_1] <getline >May-01-14 20:42:26 [Worker_1] <getline: <EHLO a13-36.smtp-out.amazonses.com[CR][LF] > >May-01-14 20:42:26 [Worker_1] <info: reuse DNS socket for 216.187.125.130 >May-01-14 20:42:26 [Worker_1] <info: reuse DNS socket for 216.187.125.131 >May-01-14 20:42:26 [Worker_1] <headerWrap >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xdf79ca8) l=28 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xdf79ca8) l=28 >May-01-14 20:42:26 [Worker_1] <wrote: IO::Socket::INET=GLOB(0xdf79ca8) (28) >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - read OK >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - process read >May-01-14 20:42:26 [Worker_1] <doing line <250-spiffy.unpatented.com Hello spiffy.unpatented.com [66.135.57.44][CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-spiffy.unpatented.com Hello spiffy.unpatented.com [66.135.57.44][CR][LF] >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noTLSIP >May-01-14 20:42:26 [Worker_1] <injected 250-STARTTLS >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noTLSIP >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=84 >May-01-14 20:42:26 [Worker_1] <doing line <250-SIZE 52428800[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-SIZE 52428800[CR][LF] >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=19 >May-01-14 20:42:26 [Worker_1] <doing line <250-8BITMIME[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-8BITMIME[CR][LF] >May-01-14 20:42:26 [Worker_1] <250-sequenz - from server: >250-8BITMIME[CR][LF] < >May-01-14 20:42:26 [Worker_1] <250-sequenz - to client: >< >May-01-14 20:42:26 [Worker_1] <doing line <250-PIPELINING[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-PIPELINING[CR][LF] >May-01-14 20:42:26 [Worker_1] <250-sequenz - from server: >250-PIPELINING[CR][LF] < >May-01-14 20:42:26 [Worker_1] <250-sequenz - to client: >< >May-01-14 20:42:26 [Worker_1] <doing line <250-AUTH PLAIN LOGIN[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-AUTH PLAIN LOGIN[CR][LF] >May-01-14 20:42:26 [Worker_1] <info: Reply: registered authmethode PLAIN >May-01-14 20:42:26 [Worker_1] <info: Reply: registered authmethode LOGIN >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=22 >May-01-14 20:42:26 [Worker_1] <doing line <250-STARTTLS[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250-STARTTLS[CR][LF] >May-01-14 20:42:26 [Worker_1] <doing line <250 HELP[CR][LF] > >May-01-14 20:42:26 [Worker_1] <reply - 250 HELP[CR][LF] >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xdf79ca8) l= >May-01-14 20:42:26 [Worker_1] <noop to server 1 >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=10 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xdf79ca8) l=0 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 l=135 >May-01-14 20:42:26 [Worker_1] <wrote: IO::Socket::INET=GLOB(0xf567a10) 54.240.13.36 (135) >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - read OK >May-01-14 20:42:26 [Worker_1] <SMTPTraffic - process read >May-01-14 20:42:26 [Worker_1] <doing line <STARTTLS[CR][LF] > >May-01-14 20:42:26 [Worker_1] <getline >May-01-14 20:42:26 [Worker_1] <getline: <STARTTLS[CR][LF] > >May-01-14 20:42:26 [Worker_1] <matchIP - 54.240.13.36 - noTLSIP >May-01-14 20:42:26 [Worker_1] <sq: IO::Socket::INET=GLOB(0xdf79ca8) l=10 >May-01-14 20:42:26 [Worker_1] <IO::Socket::INET=GLOB(0xdf79ca8) l=10 >May-01-14 20:42:26 [Worker_1] <wrote: IO::Socket::INET=GLOB(0xdf79ca8) (10) >May-01-14 20:42:27 [Worker_1] <SMTPTraffic - read OK >May-01-14 20:42:27 [Worker_1] <SMTPTraffic - process read >May-01-14 20:42:27 [Worker_1] <doing line <220 TLS go ahead[CR][LF] > >May-01-14 20:42:27 [Worker_1] <reply - 220 TLS go ahead[CR][LF] >May-01-14 20:42:27 [Worker_1] <illegal STARTTLS request without TLS ready from server >May-01-14 20:42:27 [Worker_1] <matchIP - 54.240.13.36 - noTLSIP >May-01-14 20:42:27 [Worker_1] <NoLoopSyswrite >May-01-14 20:42:27 [Worker_1] <NoLoopSyswrite - write(30 IO::Socket::INET=GLOB(0xf567a10)): '220 TLS go ahead[CR][LF] ' - 18 >May-01-14 20:42:27 [Worker_1] <NoLoopSyswrite - wrote: 18 to IO::Socket::INET=GLOB(0xf567a10) >May-01-14 20:42:27 [Worker_1] <TimeZoneDiff: -25200 seconds to GMT >May-01-14 20:42:27 [Worker_1] <headerWrap >May-01-14 20:42:27 [Worker_1] Info: notification message queued to sent to ad...@admin.com May-01-14 20:42:27 [Worker_1] 54.240.13.36 error: Couldn't upgrade to TLS for client 54.240.13.36: SSL connect accept failed because of handshake problems error:14094438:SSL routines:SSL3_READ_BYTES:tlsv1 alert internal error Thomas Eckardt said the following on 5/1/2014 6:23 AM: >>> May-01-14 04:48:03 [Worker_1] <matchIP - 54.240.15.111 - noTLSIP > This special case has to be fixed. > - ASSP has removed the 'STARTTLS' offer for IP '54.240.15.111' > - how ever, this stupid client uses the STARTTLS command > - the assp BUG accepts the STARTTLS instead to reply '502 not implemeted' > - the SSL handshake failes > > see: > https://bugs.launchpad.net/ubuntu/+source/openssl/+bug/861137 > http://openssl.6102.n7.nabble.com/Client-certificate-chains-td26513.html > or simply search the net for 'openssl error:14094438' > > >> With the SSL Debug log level setting, I am rather unclear which setting >> is considered the highest, Level 1 or Level 3? > > Set the debug-level for SSL/TLS. Than higher the level, than more > information are written to STDOUT! > To be clear - 1 is less than 3 - so level 1 is less than level 3 :) > > Thomas > > ------------------------------------------------------------------------------ "Accelerate Dev Cycles with Automated Cross-Browser Testing - For FREE Instantly run your Selenium tests across 300+ browser/OS combos. Get unparalleled scalability from the best Selenium testing platform available. Simple to use. Nothing to install. Get started now for free." http://p.sf.net/sfu/SauceLabs _______________________________________________ Assp-user mailing list Assp-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/assp-user
