[stunnel-users] Error with negotiation OK

Tue May 15 12:04:34 CEST 2018

Hi,

IMO, this problem has nothing to do with stunnel.

There are plenty of issues reported on the web, most of them related to
Outlook.

Does it happen with all email addresses or a specific one ?

Flo

On Tue, May 15, 2018 at 9:56 AM, Alix Janeth Jerez <alixj at hotmail.com>
wrote:

> Hi
>
> I am using lastest stunnel version.
>
> When i try to send an email, i get:
>
> *"error permanente de SMTP: 503 Bad sequence of commands".*
>
> This is the trace generated when I try to send an email.
>
>  2018.05.14 12:59:08 LOG5[main]: Reading configuration from file
> stunnel.conf
>  2018.05.14 12:59:08 LOG5[main]: UTF-8 byte order mark not detected
>  2018.05.14 12:59:08 LOG5[main]: FIPS mode disabled
>  2018.05.14 12:59:08 LOG5[main]: Configuration successful
>  2018.05.14 12:59:08 LOG7[main]: Binding service [pseudo-ssmtp]
>  2018.05.14 12:59:08 LOG7[main]: Listening file descriptor created (FD=568)
>  2018.05.14 12:59:08 LOG7[main]: Option SO_EXCLUSIVEADDRUSE set on accept
> socket
>  2018.05.14 12:59:08 LOG7[main]: Service [pseudo-ssmtp] (FD=568) bound to
> 172.31.41.84:116
>  2018.05.14 12:59:08 LOG7[main]: Signal pipe is empty
>  2018.05.14 12:59:22 LOG7[main]: Found 1 ready file descriptor(s)
>  2018.05.14 12:59:22 LOG7[main]: FD=324 ifds=r-x ofds=r--
>  2018.05.14 12:59:22 LOG7[main]: Dispatching signals from the signal pipe
>  2018.05.14 12:59:22 LOG7[main]: Processing SIGNAL_RELOAD_CONFIG
>  2018.05.14 12:59:22 LOG7[main]: Running on Windows 6.1
>  2018.05.14 12:59:22 LOG5[main]: Reading configuration from file
> stunnel.conf
>  2018.05.14 12:59:22 LOG5[main]: UTF-8 byte order mark not detected
>  2018.05.14 12:59:22 LOG5[main]: FIPS mode disabled
>  2018.05.14 12:59:22 LOG7[main]: Compression disabled
>  2018.05.14 12:59:22 LOG7[main]: Snagged 64 random bytes from C:/.rnd
>  2018.05.14 12:59:22 LOG7[main]: Wrote 1024 new random bytes to C:/.rnd
>  2018.05.14 12:59:22 LOG7[main]: PRNG seeded successfully
>  2018.05.14 12:59:22 LOG6[main]: Initializing service [pseudo-ssmtp]
>  2018.05.14 12:59:22 LOG7[main]: Ciphers: HIGH:!DH:!aNULL:!SSLv2
>  2018.05.14 12:59:22 LOG7[main]: TLS options: 0x03000004 (+0x03000000,
> 0x00000000)
>  2018.05.14 12:59:22 LOG6[main]: Loading certificate from file: stunnel.pem
>  2018.05.14 12:59:22 LOG6[main]: Certificate loaded from file: stunnel.pem
>  2018.05.14 12:59:22 LOG6[main]: Loading private key from file: stunnel.pem
>  2018.05.14 12:59:22 LOG6[main]: Private key loaded from file: stunnel.pem
>  2018.05.14 12:59:22 LOG7[main]: Private key check succeeded
>  2018.05.14 12:59:22 LOG5[main]: Configuration successful
>  2018.05.14 12:59:22 LOG7[main]: Unbinding service [pseudo-ssmtp]
>  2018.05.14 12:59:22 LOG7[main]: Service [pseudo-ssmtp] closed (FD=568)
>  2018.05.14 12:59:22 LOG7[main]: Service [pseudo-ssmtp] closed
>  2018.05.14 12:59:22 LOG7[main]: Binding service [pseudo-ssmtp]
>  2018.05.14 12:59:22 LOG7[main]: Listening file descriptor created (FD=568)
>  2018.05.14 12:59:22 LOG7[main]: Option SO_EXCLUSIVEADDRUSE set on accept
> socket
>  2018.05.14 12:59:22 LOG7[main]: Service [pseudo-ssmtp] (FD=568) bound to
> 172.31.41.84:116
>  2018.05.14 12:59:22 LOG7[main]: Signal pipe is empty
>  2018.05.14 12:59:34 LOG7[main]: Found 1 ready file descriptor(s)
>  2018.05.14 12:59:34 LOG7[main]: FD=324 ifds=r-x ofds=---
>  2018.05.14 12:59:34 LOG7[main]: Service [pseudo-ssmtp] accepted (FD=584)
> from 172.31.41.84:53557
>  2018.05.14 12:59:34 LOG7[main]: Creating a new thread
>  2018.05.14 12:59:34 LOG7[main]: New thread created
>  2018.05.14 12:59:34 LOG7[37]: Service [pseudo-ssmtp] started
>  2018.05.14 12:59:34 LOG7[37]: Option TCP_NODELAY set on local socket
>  2018.05.14 12:59:34 LOG5[37]: Service [pseudo-ssmtp] accepted connection
> from 172.31.41.84:53557
>  2018.05.14 12:59:34 LOG6[37]: failover: round-robin, starting at entry #1
>  2018.05.14 12:59:34 LOG6[37]: s_connect: connecting 212.227.15.158:465
>  2018.05.14 12:59:34 LOG7[37]: s_connect: s_poll_wait 212.227.15.158:465:
> waiting 10 seconds
> 2018.05.14 12:59:34 LOG5[37]: s_connect: connected 212.227.15.158:465
> 2018.05.14 12:59:34 LOG5[37]: Service [pseudo-ssmtp] connected remote
> server from 172.31.41.84:53558
> 2018.05.14 12:59:34 LOG7[37]: Option TCP_NODELAY set on remote socket
> 2018.05.14 12:59:34 LOG7[37]: Remote descriptor (FD=552) initialized
> 2018.05.14 12:59:34 LOG6[37]: SNI: sending servername: smtp.1and1.es
> 2018.05.14 12:59:34 LOG6[37]: Peer certificate required
> 2018.05.14 12:59:34 LOG7[37]: TLS state (connect): before/connect
> initialization
> 2018.05.14 12:59:34 LOG7[37]: TLS state (connect): SSLv2/v3 write client
> hello A
> 2018.05.14 12:59:34 LOG7[37]: TLS state (connect): SSLv3 read server hello
> A
> 2018.05.14 12:59:34 LOG7[37]: Verification started at depth=2: C=US,
> O="thawte, Inc.", OU=Certification Services Division, OU="(c) 2006 thawte,
> Inc. - For authorized use only", CN=thawte Primary Root CA
> 2018.05.14 12:59:34 LOG7[37]: CERT: Pre-verification succeeded
> 2018.05.14 12:59:34 LOG7[37]: OCSP: Ignoring root certificate
> 2018.05.14 12:59:34 LOG6[37]: Certificate accepted at depth=2: C=US,
> O="thawte, Inc.", OU=Certification Services Division, OU="(c) 2006 thawte,
> Inc. - For authorized use only", CN=thawte Primary Root CA
> 2018.05.14 12:59:34 LOG7[37]: Verification started at depth=1: C=US,
> O="thawte, Inc.", CN=thawte SSL CA - G2
> 2018.05.14 12:59:34 LOG7[37]: CERT: Pre-verification succeeded
> 2018.05.14 12:59:34 LOG5[37]: OCSP: Connecting the AIA responder "
> http://t2.symcb.com"
> 2018.05.14 12:59:34 LOG6[37]: s_connect: connecting 23.5.251.27:80
> 2018.05.14 12:59:34 LOG7[37]: s_connect: s_poll_wait 23.5.251.27:80:
> waiting 10 seconds
> 2018.05.14 12:59:34 LOG5[37]: s_connect: connected 23.5.251.27:80
> 2018.05.14 12:59:34 LOG7[37]: OCSP: Connected t2.symcb.com:80
> 2018.05.14 12:59:34 LOG7[37]: OCSP: Response received
> 2018.05.14 12:59:34 LOG6[37]: OCSP: Status: good
> 2018.05.14 12:59:34 LOG6[37]: OCSP: This update: May 13 18:15:02 2018 GMT
> 2018.05.14 12:59:34 LOG6[37]: OCSP: Next update: May 20 18:15:02 2018 GMT
> 2018.05.14 12:59:34 LOG5[37]: OCSP: Certificate accepted
> 2018.05.14 12:59:34 LOG6[37]: Certificate accepted at depth=1: C=US, O="thawte,
> Inc.", CN=thawte SSL CA - G2
> 2018.05.14 12:59:34 LOG7[37]: Verification started at depth=0: C=DE,
> ST=Rheinland-Pfalz, L=Montabaur, O=1&1 Internet SE, CN=smtp.1and1.es
> 2018.05.14 12:59:34 LOG7[37]: CERT: Pre-verification succeeded
> 2018.05.14 12:59:34 LOG6[37]: CERT: Host name "smtp.1and1.es" matched
> with "smtp.1and1.es"
> 2018.05.14 12:59:34 LOG5[37]: OCSP: Connecting the AIA responder "
> http://tj.symcd.com"
> 2018.05.14 12:59:34 LOG6[37]: s_connect: connecting 23.5.251.27:80
> 2018.05.14 12:59:34 LOG7[37]: s_connect: s_poll_wait 23.5.251.27:80:
> waiting 10 seconds
> 2018.05.14 12:59:35 LOG5[37]: s_connect: connected 23.5.251.27:80
> 2018.05.14 12:59:35 LOG7[37]: OCSP: Connected tj.symcd.com:80
> 2018.05.14 12:59:35 LOG7[37]: OCSP: Response received
> 2018.05.14 12:59:35 LOG6[37]: OCSP: Status: good
> 2018.05.14 12:59:35 LOG6[37]: OCSP: This update: May 14 01:38:59 2018 GMT
> 2018.05.14 12:59:35 LOG6[37]: OCSP: Next update: May 21 01:38:59 2018 GMT
> 2018.05.14 12:59:35 LOG5[37]: OCSP: Certificate accepted
> 2018.05.14 12:59:35 LOG5[37]: Certificate accepted at depth=0: C=DE,
> ST=Rheinland-Pfalz, L=Montabaur, O=1&1 Internet SE, CN=smtp.1and1.es
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 read server
> certificate A
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 read server key
> exchange A
> 2018.05.14 12:59:35 LOG6[37]: Client certificate not requested
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 read server done A
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 write client key
> exchange A
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 write change
> cipher spec A
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 write finished A
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 flush data
> 2018.05.14 12:59:35 LOG7[37]: TLS state (connect): SSLv3 read finished A
> 2018.05.14 12:59:35 LOG7[37]:      1 client connect(s) requested
> 2018.05.14 12:59:35 LOG7[37]:      1 client connect(s) succeeded
> 2018.05.14 12:59:35 LOG7[37]:      0 client renegotiation(s) requested
> 2018.05.14 12:59:35 LOG7[37]:      0 session reuse(s)
> 2018.05.14 12:59:35 LOG6[37]: TLS connected: new session negotiated
> 2018.05.14 12:59:35 LOG7[37]: Peer certificate was cached (5543 bytes)
> 2018.05.14 12:59:35 LOG6[37]: Negotiated TLSv1.2 ciphersuite
> ECDHE-RSA-AES256-GCM-SHA384 (256-bit encryption)
> 2018.05.14 12:59:35 LOG7[37]: Compression: null, expansion: null
> 2018.05.14 12:59:53 LOG3[36]: transfer: s_poll_wait: TIMEOUTclose
> exceeded: closing
> 2018.05.14 12:59:53 LOG5[36]: Connection closed: 15 byte(s) sent to TLS,
> 166 byte(s) sent to socket
>
> I can't find the error.
>
> Thanks in advance for your help.
>
>
> Best regards,
>
> Alix
>
> _______________________________________________
> stunnel-users mailing list
> stunnel-users at stunnel.org
> https://www.stunnel.org/cgi-bin/mailman/listinfo/stunnel-users
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.stunnel.org/pipermail/stunnel-users/attachments/20180515/cb2fa91b/attachment.html>