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

Fri Jul 22 09:44:33 PDT 2016

The quickfix/n event log should give you a hint about why the disconnect
(i.e. OnLogout) occurred.
If you can post your event log and your (sanitized if necessary) messages
log to list maybe we can help you further.

--
Mike Gatny
Connamara Systems, LLC

On Fri, Jul 22, 2016 at 10:36 AM, dai davy <davydai at msn.com> wrote:

> 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>应用
>
>
>
> _______________________________________________
> Quickfixn mailing list
> Quickfixn at lists.quickfixn.com
> http://lists.quickfixn.com/listinfo.cgi/quickfixn-quickfixn.com
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.quickfixn.com/pipermail/quickfixn-quickfixn.com/attachments/20160722/28d2ec11/attachment-0002.htm>