[stunnel-users] Error with negotiation OK

Alix Janeth Jerez alixj at hotmail.com
Tue May 15 09:56:05 CEST 2018


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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.stunnel.org/pipermail/stunnel-users/attachments/20180515/c8e5c843/attachment-0001.html>


More information about the stunnel-users mailing list