{{Quickfixn}} Logon message must be stuck in Stunnel

dai davy davydai at msn.com
Fri Jul 22 07:36:02 PDT 2016 

After I sent logon message, the OnLogout callback was always called. And LMAX confirmed no message hit their server. Could anybody tell me the prolem cause?Thank you!

My cfg file of QuickFix/n as follows:
[DEFAULT]
ConnectionType=initiator
ReconnectInterval=2
FileStorePath=store
FileLogPath=log
StartTime=00:00:00
EndTime=24:00:00
ResetOnLogon=Y
ResetOnLogout=Y
ResetOnDisconnect=Y
CheckLatency=N

[SESSION]
BeginString=FIX.4.4
SenderCompID=davy123
TargetCompID=LMXBDM
HeartBtInt=60
#SocketConnectPort=443
#SocketConnectHost=fix-marketdata.london-demo.lmax.com
SocketConnectPort=4003
SocketConnectHost=127.0.0.1
DataDictionary=LMAX-FIX-MarketData-API-QuickFix-DataDictionary.xml

My cfg of Stunnel as follows:
cert = stunnel.pem
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
debug = 7

fips = yes

[LMAX]
client = yes
accept = 127.0.0.1:4003
connect = fix-marketdata.london-demo.lmax.com:443
sslVersion = TLSv1
options = NO_SSLv2
options = NO_SSLv3

The log of stunnel is as follows:
The client connections succeed, but ssll sent close_notify_alert and shutdown.

2016.07.22 22:27:40 LOG7[cron]: Cron thread initialized
2016.07.22 22:27:40 LOG7[main]: No limit detected for the number of clients
2016.07.22 22:27:40 LOG5[main]: stunnel 5.34 on x86-pc-msvc-1500 platform
2016.07.22 22:27:40 LOG5[main]: Compiled/running with OpenSSL 1.0.2h-fips  3 May 2016
2016.07.22 22:27:40 LOG5[main]: Threading:WIN32 Sockets:SELECT,IPv6 TLS:ENGINE,FIPS,OCSP,PSK,SNI
2016.07.22 22:27:40 LOG7[main]: errno: (*_errno())
2016.07.22 22:27:40 LOG7[ui]: GUI message loop initialized
2016.07.22 22:27:40 LOG5[main]: Reading configuration from file stunnel.conf
2016.07.22 22:27:40 LOG5[main]: UTF-8 byte order mark detected
2016.07.22 22:27:40 LOG5[main]: FIPS mode enabled
2016.07.22 22:27:40 LOG7[main]: Compression disabled
2016.07.22 22:27:40 LOG7[main]: Snagged 64 random bytes from C:/.rnd
2016.07.22 22:27:40 LOG7[main]: Wrote 0 new random bytes to C:/.rnd
2016.07.22 22:27:40 LOG7[main]: PRNG seeded successfully
2016.07.22 22:27:40 LOG6[main]: Initializing service [LMAX]
2016.07.22 22:27:41 LOG6[main]: Loading certificate from file: stunnel.pem
2016.07.22 22:27:41 LOG6[main]: Certificate loaded from file: stunnel.pem
2016.07.22 22:27:41 LOG6[main]: Loading private key from file: stunnel.pem
2016.07.22 22:27:41 LOG6[main]: Private key loaded from file: stunnel.pem
2016.07.22 22:27:41 LOG7[main]: Private key check succeeded
2016.07.22 22:27:41 LOG4[main]: Service [LMAX] needs authentication to prevent MITM attacks
2016.07.22 22:27:41 LOG7[main]: SSL options: 0x03000004 (+0x03000000, -0x00000000)
2016.07.22 22:27:41 LOG5[main]: Configuration successful
2016.07.22 22:27:41 LOG7[main]: Listening file descriptor created (FD=668)
2016.07.22 22:27:41 LOG7[main]: Service [LMAX] (FD=668) bound to 127.0.0.1:4003
2016.07.22 22:27:51 LOG7[main]: Found 1 ready file descriptor(s)
2016.07.22 22:27:51 LOG7[main]: FD=620 ifds=r-x ofds=---
2016.07.22 22:27:51 LOG7[main]: Service [LMAX] accepted (FD=956) from 127.0.0.1:2106
2016.07.22 22:27:51 LOG7[main]: Creating a new thread
2016.07.22 22:27:51 LOG7[main]: New thread created
2016.07.22 22:27:51 LOG7[0]: Service [LMAX] started
2016.07.22 22:27:51 LOG5[0]: Service [LMAX] accepted connection from 127.0.0.1:2106
2016.07.22 22:27:51 LOG6[0]: s_connect: connecting 91.215.166.66:443
2016.07.22 22:27:51 LOG7[0]: s_connect: s_poll_wait 91.215.166.66:443: waiting 10 seconds
2016.07.22 22:27:51 LOG5[0]: s_connect: connected 91.215.166.66:443
2016.07.22 22:27:51 LOG5[0]: Service [LMAX] connected remote server from 192.168.3.94:2107
2016.07.22 22:27:51 LOG7[0]: Remote descriptor (FD=964) initialized
2016.07.22 22:27:51 LOG6[0]: SNI: sending servername: fix-marketdata.london-demo.lmax.com
2016.07.22 22:27:51 LOG7[0]: SSL state (connect): before/connect initialization
2016.07.22 22:27:51 LOG7[0]: SSL state (connect): SSLv3 write client hello A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read server hello A
2016.07.22 22:27:52 LOG6[0]: Certificate verification disabled
2016.07.22 22:27:52 LOG6[0]: Certificate verification disabled
2016.07.22 22:27:52 LOG6[0]: Certificate verification disabled
2016.07.22 22:27:52 LOG6[0]: Certificate verification disabled
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read server certificate A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read server key exchange A
2016.07.22 22:27:52 LOG6[0]: Client certificate not requested
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read server done A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 write client key exchange A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 write change cipher spec A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 write finished A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 flush data
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read server session ticket A
2016.07.22 22:27:52 LOG7[0]: SSL state (connect): SSLv3 read finished A
2016.07.22 22:27:52 LOG7[0]:      1 client connect(s) requested
2016.07.22 22:27:52 LOG7[0]:      1 client connect(s) succeeded
2016.07.22 22:27:52 LOG7[0]:      0 client renegotiation(s) requested
2016.07.22 22:27:52 LOG7[0]:      0 session reuse(s)
2016.07.22 22:27:52 LOG6[0]: SSL connected: new session negotiated
2016.07.22 22:27:52 LOG7[0]: Peer certificate was cached (4827 bytes)
2016.07.22 22:27:52 LOG6[0]: Negotiated TLSv1 ciphersuite ECDHE-RSA-AES256-SHA (256-bit encryption)
2016.07.22 22:27:52 LOG7[0]: Compression: null, expansion: null
2016.07.22 22:27:52 LOG7[0]: SSL alert (read): warning: close notify
2016.07.22 22:27:52 LOG6[0]: SSL closed (SSL_read)
2016.07.22 22:27:52 LOG7[0]: Sent socket write shutdown
2016.07.22 22:27:52 LOG6[0]: Read socket closed (readsocket)
2016.07.22 22:27:52 LOG7[0]: Sending close_notify alert
2016.07.22 22:27:52 LOG7[0]: SSL alert (write): warning: close notify
2016.07.22 22:27:52 LOG6[0]: SSL_shutdown successfully sent close_notify alert
2016.07.22 22:27:52 LOG5[0]: Connection closed: 96 byte(s) sent to SSL, 97 byte(s) sent to socket
2016.07.22 22:27:52 LOG7[0]: Remote descriptor (FD=964) closed
2016.07.22 22:27:52 LOG7[0]: Local descriptor (FD=956) closed
2016.07.22 22:27:52 LOG7[0]: Service [LMAX] finished (0 left)
2016.07.22 22:27:53 LOG7[main]: Found 1 ready file descriptor(s)
2016.07.22 22:27:53 LOG7[main]: FD=620 ifds=r-x ofds=---
2016.07.22 22:27:53 LOG7[main]: Service [LMAX] accepted (FD=976) from 127.0.0.1:2108
2016.07.22 22:27:53 LOG7[main]: Creating a new thread
2016.07.22 22:27:53 LOG7[main]: New thread created
2016.07.22 22:27:53 LOG7[1]: Service [LMAX] started
2016.07.22 22:27:53 LOG5[1]: Service [LMAX] accepted connection from 127.0.0.1:2108
2016.07.22 22:27:53 LOG6[1]: s_connect: connecting 91.215.166.66:443
2016.07.22 22:27:53 LOG7[1]: s_connect: s_poll_wait 91.215.166.66:443: waiting 10 seconds
2016.07.22 22:27:53 LOG5[1]: s_connect: connected 91.215.166.66:443
2016.07.22 22:27:53 LOG5[1]: Service [LMAX] connected remote server from 192.168.3.94:2109
2016.07.22 22:27:53 LOG7[1]: Remote descriptor (FD=964) initialized
2016.07.22 22:27:53 LOG6[1]: SNI: sending servername: fix-marketdata.london-demo.lmax.com
2016.07.22 22:27:53 LOG7[1]: SSL state (connect): before/connect initialization
2016.07.22 22:27:53 LOG7[1]: SSL state (connect): SSLv3 write client hello A
2016.07.22 22:27:55 LOG7[1]: SSL state (connect): SSLv3 read server hello A
2016.07.22 22:27:55 LOG7[1]: SSL state (connect): SSLv3 read finished A
2016.07.22 22:27:55 LOG7[1]: SSL state (connect): SSLv3 write change cipher spec A
2016.07.22 22:27:55 LOG7[1]: SSL state (connect): SSLv3 write finished A
2016.07.22 22:27:55 LOG7[1]: SSL state (connect): SSLv3 flush data
2016.07.22 22:27:55 LOG7[1]:      2 client connect(s) requested
2016.07.22 22:27:55 LOG7[1]:      2 client connect(s) succeeded
2016.07.22 22:27:55 LOG7[1]:      0 client renegotiation(s) requested
2016.07.22 22:27:55 LOG7[1]:      1 session reuse(s)
2016.07.22 22:27:55 LOG6[1]: SSL connected: previous session reused
2016.07.22 22:27:56 LOG6[1]: Read socket closed (readsocket)
2016.07.22 22:27:56 LOG7[1]: Sending close_notify alert
2016.07.22 22:27:56 LOG7[1]: SSL alert (write): warning: close notify
2016.07.22 22:27:56 LOG6[1]: SSL_shutdown successfully sent close_notify alert
2016.07.22 22:27:57 LOG7[main]: Found 1 ready file descriptor(s)
2016.07.22 22:27:57 LOG7[main]: FD=620 ifds=r-x ofds=---
2016.07.22 22:27:57 LOG7[main]: Service [LMAX] accepted (FD=988) from 127.0.0.1:2110
2016.07.22 22:27:57 LOG7[main]: Creating a new thread
2016.07.22 22:27:57 LOG7[main]: New thread created
2016.07.22 22:27:57 LOG7[2]: Service [LMAX] started
2016.07.22 22:27:57 LOG5[2]: Service [LMAX] accepted connection from 127.0.0.1:2110
2016.07.22 22:27:57 LOG6[2]: s_connect: connecting 91.215.166.66:443
2016.07.22 22:27:57 LOG7[2]: s_connect: s_poll_wait 91.215.166.66:443: waiting 10 seconds
2016.07.22 22:27:57 LOG5[2]: s_connect: connected 91.215.166.66:443
2016.07.22 22:27:57 LOG5[2]: Service [LMAX] connected remote server from 192.168.3.94:2111
2016.07.22 22:27:57 LOG7[2]: Remote descriptor (FD=1008) initialized
2016.07.22 22:27:57 LOG6[2]: SNI: sending servername: fix-marketdata.london-demo.lmax.com
2016.07.22 22:27:57 LOG7[2]: SSL state (connect): before/connect initialization
2016.07.22 22:27:57 LOG7[2]: SSL state (connect): SSLv3 write client hello A
2016.07.22 22:27:58 LOG7[2]: SSL state (connect): SSLv3 read server hello A
2016.07.22 22:27:58 LOG7[2]: SSL state (connect): SSLv3 read finished A
2016.07.22 22:27:58 LOG7[2]: SSL state (connect): SSLv3 write change cipher spec A
2016.07.22 22:27:58 LOG7[2]: SSL state (connect): SSLv3 write finished A
2016.07.22 22:27:58 LOG7[2]: SSL state (connect): SSLv3 flush data
2016.07.22 22:27:58 LOG7[2]:      3 client connect(s) requested
2016.07.22 22:27:58 LOG7[2]:      3 client connect(s) succeeded
2016.07.22 22:27:58 LOG7[2]:      0 client renegotiation(s) requested
2016.07.22 22:27:58 LOG7[2]:      2 session reuse(s)
2016.07.22 22:27:58 LOG6[2]: SSL connected: previous session reused
2016.07.22 22:27:58 LOG7[2]: SSL alert (read): warning: close notify
2016.07.22 22:27:58 LOG6[2]: SSL closed (SSL_read)
2016.07.22 22:27:58 LOG7[2]: Sent socket write shutdown
2016.07.22 22:27:58 LOG6[2]: Read socket closed (readsocket)
2016.07.22 22:27:58 LOG7[2]: Sending close_notify alert
2016.07.22 22:27:58 LOG7[2]: SSL alert (write): warning: close notify
2016.07.22 22:27:58 LOG6[2]: SSL_shutdown successfully sent close_notify alert
2016.07.22 22:27:58 LOG5[2]: Connection closed: 96 byte(s) sent to SSL, 97 byte(s) sent to socket
2016.07.22 22:27:58 LOG7[2]: Remote descriptor (FD=1008) closed
2016.07.22 22:27:58 LOG7[2]: Local descriptor (FD=988) closed
2016.07.22 22:27:58 LOG7[2]: Service [LMAX] finished (1 left)
2016.07.22 22:28:40 LOG6[cron]: Executing cron jobs
2016.07.22 22:28:40 LOG6[cron]: Cron jobs completed in 0 seconds
2016.07.22 22:28:40 LOG7[cron]: Waiting 86400 seconds
2016.07.22 22:28:56 LOG3[1]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2016.07.22 22:28:56 LOG5[1]: Connection closed: 96 byte(s) sent to SSL, 97 byte(s) sent to socket
2016.07.22 22:28:56 LOG7[1]: Remote descriptor (FD=964) closed
2016.07.22 22:28:56 LOG7[1]: Local descriptor (FD=976) closed
2016.07.22 22:28:56 LOG7[1]: Service [LMAX] finished (0 left)

发送自 Windows 10 版邮件<https://go.microsoft.com/fwlink/?LinkId=550986>应用

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.quickfixn.com/pipermail/quickfixn-quickfixn.com/attachments/20160722/5f42d4b2/attachment-0001.htm>

More information about the Quickfixn mailing list