TimelordUK / jspurefix

native typescript FIX engine
MIT License
58 stars 27 forks source link

Logout after close #56

Closed pcicman closed 8 months ago

pcicman commented 1 year ago

When the remote closes the socket during a running session, the following kicks in (FixSession):

rx.on('done', () => {
    logger.info('rx done received')
    this.done()
})

This will trigger session logout, which in turn will attempt to send Logout through the closed connection and fails with:

error: unexpected state - transport failed? = WaitingLogoutConfirm : Error: unexpected state - transport failed? = WaitingLogoutConfirm.

Should not this state transition (after socket close) instead prevent sending any further messages and terminate instead so the session can be recovered and reconnected?

This also causes problems with message persistence, as persisting the failed Logout message will increase the sequence for the next login, which will, in turn, cause Resend/Reset after the next Logon.

TimelordUK commented 1 year ago

Yes this looks like an issue.  Will there be a PR for it ?  I will take a look shortly but yes we should not try and send messages on transport failed state.  Sent from my iPhoneOn 22 Nov 2022, at 08:02, Peter Cicman @.***> wrote: When the remote closes the socket during a running session, the following kicks in (FixSession): rx.on('done', () => { logger.info('rx done received') this.done() })

This will trigger session logout, which in turn will attempt to send Logout through the closed connection and fails with: error: unexpected state - transport failed? = WaitingLogoutConfirm : Error: unexpected state - transport failed? = WaitingLogoutConfirm. Should not this state transition (after socket close) instead prevent sending any further messages and terminate instead so the session can be recovered and reconnected? This also causes problems with message persistence, as persisting the failed Logout message will increase the sequence for the next login, which will, in turn, cause Resend/Reset after the next Logon.

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you are subscribed to this thread.Message ID: @.***>

pcicman commented 1 year ago

I've dug a bit deeper, but it's hard to follow the implementation. We have both done and end events coming from the AsciiParser. done is triggered after finish on the Writable and will always precede the end event.

The FiXml parser seems to emit close instead of done for the same(?) use case. The close event do not seem to be handled by FixSession.

In both scenarios though, I would expect the socket to be already closed. Therefore IMO no message should be sent after done() is invoked regardless of the state and the only remaining action is either to either terminate with an error or to stop gracefully. Would you agree?

TimelordUK commented 1 year ago

yes I will look at what is going on - clearly we should not try and initiate a logout when the physical transport has failed

TimelordUK commented 1 year ago

i have had a go at improving this on branch linting - it is still being tested and not yet released to npm. However running recovering skeleton demo we see this exchange of messages

note we logon do not reset seqNo - then the socket is torn down the client errors and recovers without logging out - we reconnect and go on to logon with preserved seqNo and send a heartbeat. We logout and close gracefully on new session

A [Logon] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 117,
        "MsgType": "A",
        "SenderCompID": "init-comp",
        "TargetCompID": "accept-comp",
        "MsgSeqNum": 1,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:21:34.596Z"
    },
    "EncryptMethod": 0,
    "HeartBtInt": 30,
    "ResetSeqNumFlag": false,
    "Username": "js-client",
    "Password": "pwd-client",
    "StandardTrailer": {
        "CheckSum": "019"
    }
}

A [Logon] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 117,
        "MsgType": "A",
        "SenderCompID": "accept-comp",
        "TargetCompID": "init-comp",
        "MsgSeqNum": 1,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:21:34.601Z"
    },
    "EncryptMethod": 0,
    "HeartBtInt": 30,
    "ResetSeqNumFlag": false,
    "Username": "js-server",
    "Password": "pwd-server",
    "StandardTrailer": {
        "CheckSum": "054"
    }
}

A [Logon] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 117,
        "MsgType": "A",
        "SenderCompID": "init-comp",
        "TargetCompID": "accept-comp",
        "MsgSeqNum": 2,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:21:44.628Z"
    },
    "EncryptMethod": 0,
    "HeartBtInt": 30,
    "ResetSeqNumFlag": false,
    "Username": "js-client",
    "Password": "pwd-client",
    "StandardTrailer": {
        "CheckSum": "017"
    }
}

A [Logon] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 117,
        "MsgType": "A",
        "SenderCompID": "accept-comp",
        "TargetCompID": "init-comp",
        "MsgSeqNum": 2,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:21:44.630Z"
    },
    "EncryptMethod": 0,
    "HeartBtInt": 30,
    "ResetSeqNumFlag": false,
    "Username": "js-server",
    "Password": "pwd-server",
    "StandardTrailer": {
        "CheckSum": "058"
    }
}

0 [Heartbeat] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 104,
        "MsgType": "0",
        "SenderCompID": "init-comp",
        "TargetCompID": "accept-comp",
        "MsgSeqNum": 3,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:22:14.795Z"
    },
    "TestReqID": "Mon, 02 Jan 2023 15:22:14 GMT",
    "StandardTrailer": {
        "CheckSum": "035"
    }
}

0 [Heartbeat] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 104,
        "MsgType": "0",
        "SenderCompID": "accept-comp",
        "TargetCompID": "init-comp",
        "MsgSeqNum": 3,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:22:14.793Z"
    },
    "TestReqID": "Mon, 02 Jan 2023 15:22:14 GMT",
    "StandardTrailer": {
        "CheckSum": "033"
    }
}

5 [Logout] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 75,
        "MsgType": "5",
        "SenderCompID": "init-comp",
        "TargetCompID": "accept-comp",
        "MsgSeqNum": 4,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:22:19.615Z"
    },
    "Text": "5",
    "StandardTrailer": {
        "CheckSum": "119"
    }
}

5 [Logout] = {
    "StandardHeader": {
        "BeginString": "FIX.4.4",
        "BodyLength": 75,
        "MsgType": "5",
        "SenderCompID": "accept-comp",
        "TargetCompID": "init-comp",
        "MsgSeqNum": 4,
        "TargetSubID": "fix",
        "SendingTime": "2023-01-02T15:22:19.618Z"
    },
    "Text": "5",
    "StandardTrailer": {
        "CheckSum": "122"
    }
}

app log

2023-01-02T15:21:34.097Z [launcher] info: launching ..
2023-01-02T15:21:34.098Z [launcher] info: creating app test_server [protocol ascii]
2023-01-02T15:21:34.099Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Datatypes.xml
2023-01-02T15:21:34.101Z [launcher] info: creating app test_client [protocol ascii]
2023-01-02T15:21:34.102Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Datatypes.xml
2023-01-02T15:21:34.102Z [launcher] info: launching ....
2023-01-02T15:21:34.112Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Fields.xml
2023-01-02T15:21:34.112Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Fields.xml
2023-01-02T15:21:34.224Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Enums.xml
2023-01-02T15:21:34.224Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Enums.xml
2023-01-02T15:21:34.328Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Components.xml
2023-01-02T15:21:34.329Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Components.xml
2023-01-02T15:21:34.344Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_rQepo\FIX.4.4\Base\Messages.xml
2023-01-02T15:21:34.344Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Messages.xml
2023-01-02T15:21:34.352Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\MsgContents.xml
2023-01-02T15:21:34.353Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\MsgContents.xml
2023-01-02T15:21:34.513Z [acceptor.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Abbreviations.xml
2023-01-02T15:21:34.513Z [initiator.RepositoryXmlParser] info: reading me\jspurefix\data\fix_repo\FIX.4.4\Base\Abbreviations.xml
2023-01-02T15:21:34.548Z [acceptor.Repository] info: definitions: 2404 fields
2023-01-02T15:21:34.548Z [acceptor.Repository] info: definitions: 111 components
2023-01-02T15:21:34.548Z [acceptor.Repository] info: definitions: 268 messages
2023-01-02T15:21:34.575Z [initiator.Repository] info: definitions: 2404 fields
2023-01-02T15:21:34.575Z [initiator.Repository] info: definitions: 111 components
2023-01-02T15:21:34.576Z [initiator.Repository] info: definitions: 268 messages
2023-01-02T15:21:34.576Z [launcher] info: create acceptor
2023-01-02T15:21:34.577Z [RespawnAcceptor] info: waitFor: waiting for acceptor respawned = 0
2023-01-02T15:21:34.577Z [acceptor] info: starting.
2023-01-02T15:21:34.577Z [test_server:TcpAcceptor] info: create unsecured server
2023-01-02T15:21:34.577Z [test_server:TcpAcceptor] info: start to listen 2344
2023-01-02T15:21:34.579Z [launcher] info: create initiator
2023-01-02T15:21:34.580Z [test_client:RecoveringTcpInitiator] info: creating an application session with DI token FixSession.
2023-01-02T15:21:34.583Z [test_client:FixSession] info: current state Idle (24) moves to DisconnectedNoConnectionToday (1)
2023-01-02T15:21:34.584Z [test_client:RecoveringTcpInitiator] info: connect: start initiator timeout 60
2023-01-02T15:21:34.584Z [test_client:FixSession] info: current state DisconnectedNoConnectionToday (1) moves to InitiateConnection (5)
2023-01-02T15:21:34.584Z [test_client:TcpInitiator] info: connecting with timeout 60
2023-01-02T15:21:34.584Z [test_client:TcpInitiator] info: unsecureDuplex try to connect to endPoint
2023-01-02T15:21:34.590Z [test_client:TcpInitiator] info: tryConnect localhost:2344
2023-01-02T15:21:34.593Z [test_server:TcpAcceptor] info: net creates session 1
2023-01-02T15:21:34.594Z [test_server:TcpAcceptor] info: new transport id = 1 created total transports = 1
2023-01-02T15:21:34.594Z [acceptor] info: creates new transport using DI token FixSession.
2023-01-02T15:21:34.595Z [test_server:FixSession] info: current state Idle (24) moves to WaitingForALogon (18)
2023-01-02T15:21:34.595Z [test_server:TcpAcceptor] info: insecure connection established
2023-01-02T15:21:34.595Z [test_client:TcpInitiator] info: net.createConnection cb, resolving
2023-01-02T15:21:34.595Z [test_client:RecoveringTcpInitiator] info: connect: receive new transport 0
2023-01-02T15:21:34.596Z [test_client:RecoveringTcpInitiator] info: initiator connects id 0
2023-01-02T15:21:34.596Z [test_client:FixSession] info: current state InitiateConnection (5) moves to NetworkConnectionEstablished (6)
2023-01-02T15:21:34.597Z [test_client:FixSession] info: current state NetworkConnectionEstablished (6) moves to InitiationLogonSent (7)
2023-01-02T15:21:34.598Z [test_client:RecoveringTcpInitiator] info: running session with transport 0 state = 7
2023-01-02T15:21:34.599Z [RespawnAcceptor] info: rxOnMsg msgType = A
2023-01-02T15:21:34.600Z [RespawnAcceptor] info: onSession: new session acceptor SenderCompID = init-comp created, count = 0}
2023-01-02T15:21:34.600Z [test_server:FixSession] info: A: Logon
2023-01-02T15:21:34.600Z [test_server:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000117
[2] 35 (MsgType) = A[Logon], [3] 49 (SenderCompID) = init-comp
[4] 56 (TargetCompID) = accept-comp, [5] 34 (MsgSeqNum) = 1
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:21:34.596
[8] 98 (EncryptMethod) = 0[None], [9] 108 (HeartBtInt) = 30
[10] 141 (ResetSeqNumFlag) = N[No], [11] 553 (Username) = js-client
[12] 554 (Password) = pwd-client, [13] 10 (CheckSum) = 019
2023-01-02T15:21:34.601Z [test_server:FixSession] info: peerLogon Username = js-client, heartBtInt = 30, peerCompId = init-comp, userName = js-client
2023-01-02T15:21:34.601Z [test_server] info: peer logs in user js-client
2023-01-02T15:21:34.601Z [test_server:FixSession] info: peerLogon onLogon returns true
2023-01-02T15:21:34.601Z [test_server:FixSession] info: current state WaitingForALogon (18) moves to InitiationLogonResponse (9)
2023-01-02T15:21:34.601Z [test_server:FixSession] info: acceptor responds to logon request
2023-01-02T15:21:34.601Z [test_server:FixSession] info: start heartbeat timer. interval = 200
2023-01-02T15:21:34.602Z [test_server:FixSession] info: system ready, inform app
2023-01-02T15:21:34.602Z [test_server] info: onReady
2023-01-02T15:21:34.602Z [test_server] info: acceptor is ready for requests - drop connection in 5
2023-01-02T15:21:34.602Z [test_client:FixSession] info: A: Logon
2023-01-02T15:21:34.602Z [test_client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000117
[2] 35 (MsgType) = A[Logon], [3] 49 (SenderCompID) = accept-comp
[4] 56 (TargetCompID) = init-comp, [5] 34 (MsgSeqNum) = 1
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:21:34.601
[8] 98 (EncryptMethod) = 0[None], [9] 108 (HeartBtInt) = 30
[10] 141 (ResetSeqNumFlag) = N[No], [11] 553 (Username) = js-server
[12] 554 (Password) = pwd-server, [13] 10 (CheckSum) = 054
2023-01-02T15:21:34.602Z [test_client:FixSession] info: peerLogon Username = js-server, heartBtInt = 30, peerCompId = accept-comp, userName = js-server
2023-01-02T15:21:34.603Z [test_client] info: peer logs in user js-server
2023-01-02T15:21:34.603Z [test_client:FixSession] info: peerLogon onLogon returns true
2023-01-02T15:21:34.603Z [test_client:FixSession] info: initiator receives logon response
2023-01-02T15:21:34.603Z [test_client:FixSession] info: current state InitiationLogonSent (7) moves to InitiationLogonReceived (8)
2023-01-02T15:21:34.603Z [test_client:FixSession] info: start heartbeat timer. interval = 200
2023-01-02T15:21:34.603Z [test_client:FixSession] info: system ready, inform app
2023-01-02T15:21:34.603Z [test_client] info: onReady
2023-01-02T15:21:34.603Z [test_client] info: will logout after 45
2023-01-02T15:21:39.603Z [test_server] info: kill transport
2023-01-02T15:21:39.604Z [test_server:FixSession] info: stopTimer
2023-01-02T15:21:39.609Z [test_server:FixSession] info: unsubscribe sessionState = [compId = accept-comp, heartBeat = 30, state = InitiationLogonResponse (9), nextTickAction = Nothing (1), now = 15:21:39.556, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:21:34.600, LastSentAt = 15:21:34.601, lastTestRequestAt = null, logoutSentAt = null, peerHeartBeatSecs = 30, peerCompId = init-comp, lastPeerMsgSeqNum = 1, LastSentSeqNum = 1, secondsSinceLogoutSent = -1, secondsSinceSent = 4.955, secondsSinceReceive = 4.956]
2023-01-02T15:21:39.609Z [test_server:FixSession] info: stop: kill transport
2023-01-02T15:21:39.609Z [test_server:FixSession] info: stop: emit error loss of tcp. test_server
2023-01-02T15:21:39.609Z [test_server:FixSession] error: loss of tcp. test_server : Error: loss of tcp. test_server
    at Immediate._onImmediate (me\jspurefix\dist\sample\tcp\recovering-skeleton\skeleton-server.js:53:31)
    at process.processImmediate (node:internal/timers:471:21)
2023-01-02T15:21:39.610Z [test_server:FixSession] info: current state InitiationLogonResponse (9) moves to Stopped (23)
2023-01-02T15:21:39.610Z [test_server] info: stopped
2023-01-02T15:21:39.610Z [acceptor] info: error in session - close listener loss of tcp. test_server
2023-01-02T15:21:39.610Z [test_server:TcpAcceptor] info: close listener on port 2344
2023-01-02T15:21:39.611Z [test_client:FixSession] info: rx end received sessionState = [compId = init-comp, heartBeat = 30, state = InitiationLogonReceived (8), nextTickAction = Nothing (1), now = 15:21:39.556, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:21:34.602, LastSentAt = 15:21:34.596, lastTestRequestAt = null, logoutSentAt = null, peerHeartBeatSecs = 30, peerCompId = accept-comp, lastPeerMsgSeqNum = 1, LastSentSeqNum = 1, secondsSinceLogoutSent = -1, secondsSinceSent = 4.96, secondsSinceReceive = 4.954]
2023-01-02T15:21:39.611Z [test_client:FixSession] info: current state InitiationLogonReceived (8) moves to DetectBrokenNetworkConnection (3)
2023-01-02T15:21:39.611Z [test_client:FixSession] info: rx error unexpected state - transport failed? = DetectBrokenNetworkConnection
2023-01-02T15:21:39.611Z [test_client:FixSession] error: unexpected state - transport failed? = DetectBrokenNetworkConnection : Error: unexpected state - transport failed? = DetectBrokenNetworkConnection
    at SkeletonClient.rxOnEnd (me\jspurefix\dist\transport\session\fix-session.js:143:23)
    at AsciiParser.<anonymous> (me\jspurefix\dist\transport\session\fix-session.js:216:73)
    at AsciiParser.emit (node:events:513:28)
    at Socket.<anonymous> (me\jspurefix\dist\buffer\ascii\ascii-parser.js:74:18)
    at Socket.emit (node:events:525:35)
    at endReadableNT (node:internal/streams/readable:1359:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
2023-01-02T15:21:39.611Z [test_client:FixSession] info: stopTimer
2023-01-02T15:21:39.611Z [test_client:FixSession] info: current state DetectBrokenNetworkConnection (3) moves to Stopped (23)
2023-01-02T15:21:39.611Z [test_client:FixSession] error: unexpected state - transport failed? = DetectBrokenNetworkConnection : Error: unexpected state - transport failed? = DetectBrokenNetworkConnection
    at SkeletonClient.rxOnEnd (me\jspurefix\dist\transport\session\fix-session.js:143:23)
    at AsciiParser.<anonymous> (me\jspurefix\dist\transport\session\fix-session.js:216:73)
    at AsciiParser.emit (node:events:513:28)
    at Socket.<anonymous> (me\jspurefix\dist\buffer\ascii\ascii-parser.js:74:18)
    at Socket.emit (node:events:525:35)
    at endReadableNT (node:internal/streams/readable:1359:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
2023-01-02T15:21:39.611Z [test_client:FixSession] info: rx done received
2023-01-02T15:21:39.611Z [test_client:FixSession] info: done. session is now stopped
2023-01-02T15:21:39.611Z [test_client:FixSession] info: done. check logout sequence state Stopped
2023-01-02T15:21:39.611Z [test_client:RecoveringTcpInitiator] info: transport id 0 failed - session state 23
2023-01-02T15:21:39.611Z [test_client:RecoveringTcpInitiator] warn: unexpected state - transport failed? = DetectBrokenNetworkConnection
2023-01-02T15:21:39.611Z [test_client:FixSession] info: ignoring request to change state as now already in Stopped
2023-01-02T15:21:39.611Z [test_client:RecoveringTcpInitiator] info: recover session transport - attempt in 5 secs
2023-01-02T15:21:39.611Z [test_client:RecoveringTcpInitiator] info: recover session set LastSentSeqNum 1 for new transport
2023-01-02T15:21:39.612Z [test_server:FixSession] info: rx end received sessionState = [compId = accept-comp, heartBeat = 30, state = Stopped (23), nextTickAction = Nothing (1), now = 15:21:39.556, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:21:34.600, LastSentAt = 15:21:34.601, lastTestRequestAt = null, logoutSentAt = null, peerHeartBeatSecs = 30, peerCompId = init-comp, lastPeerMsgSeqNum = 1, LastSentSeqNum = 1, secondsSinceLogoutSent = -1, secondsSinceSent = 4.955, secondsSinceReceive = 4.956]
2023-01-02T15:21:39.612Z [test_server:FixSession] info: rx receives end state = Stopped - stop session
2023-01-02T15:21:39.612Z [test_server:TcpAcceptor] info: transport 1 ends total transports = 0
2023-01-02T15:21:39.612Z [test_server:FixSession] info: rx done received
2023-01-02T15:21:39.612Z [test_server:FixSession] info: done. session is now stopped
2023-01-02T15:21:39.612Z [test_server:FixSession] info: done. check logout sequence state Stopped
2023-01-02T15:21:39.612Z [acceptor] info: acceptor closed.
2023-01-02T15:21:39.612Z [RespawnAcceptor] info: waitFor: error in acceptor respawned = 0
2023-01-02T15:21:39.612Z [RespawnAcceptor] info: resetLastSentSeqNo: set seqNo 1 for key init-comp
2023-01-02T15:21:39.612Z [RespawnAcceptor] info: waitFor: waiting for acceptor respawned = 1
2023-01-02T15:21:39.612Z [acceptor] info: starting.
2023-01-02T15:21:39.612Z [test_server:TcpAcceptor] info: create unsecured server
2023-01-02T15:21:39.612Z [test_server:TcpAcceptor] info: start to listen 2344
2023-01-02T15:21:44.622Z [test_client:RecoveringTcpInitiator] info: connect: start initiator timeout 60
2023-01-02T15:21:44.622Z [test_client:FixSession] info: ignoring request to change state as now already in Stopped
2023-01-02T15:21:44.623Z [test_client:TcpInitiator] info: connecting with timeout 60
2023-01-02T15:21:44.623Z [test_client:TcpInitiator] info: unsecureDuplex try to connect to endPoint
2023-01-02T15:21:44.623Z [test_client:TcpInitiator] info: tryConnect localhost:2344
2023-01-02T15:21:44.625Z [test_server:TcpAcceptor] info: net creates session 1
2023-01-02T15:21:44.626Z [test_server:TcpAcceptor] info: new transport id = 1 created total transports = 1
2023-01-02T15:21:44.627Z [acceptor] info: creates new transport using DI token FixSession.
2023-01-02T15:21:44.628Z [RespawnAcceptor] info: resetSessionSeqNo: set lastPeerSeqNum 1 for key init-comp
2023-01-02T15:21:44.628Z [test_server:FixSession] info: current state Idle (24) moves to NetworkConnectionEstablished (6)
2023-01-02T15:21:44.628Z [test_server:FixSession] info: current state NetworkConnectionEstablished (6) moves to WaitingForALogon (18)
2023-01-02T15:21:44.628Z [test_server:TcpAcceptor] info: insecure connection established
2023-01-02T15:21:44.628Z [test_client:TcpInitiator] info: net.createConnection cb, resolving
2023-01-02T15:21:44.628Z [test_client:RecoveringTcpInitiator] info: connect: receive new transport 0
2023-01-02T15:21:44.628Z [test_client:RecoveringTcpInitiator] info: initiator connects id 0
2023-01-02T15:21:44.628Z [test_client:FixSession] info: current state Stopped (23) moves to NetworkConnectionEstablished (6)
2023-01-02T15:21:44.629Z [test_client:FixSession] info: current state NetworkConnectionEstablished (6) moves to InitiationLogonSent (7)
2023-01-02T15:21:44.629Z [test_client:RecoveringTcpInitiator] info: running session with transport 0 state = 7
2023-01-02T15:21:44.629Z [test_client:RecoveringTcpInitiator] info: new transport 0
2023-01-02T15:21:44.630Z [RespawnAcceptor] info: rxOnMsg msgType = A
2023-01-02T15:21:44.630Z [RespawnAcceptor] info: onSession: new session acceptor SenderCompID = init-comp created, count = 0}
2023-01-02T15:21:44.630Z [test_server:FixSession] info: A: Logon
2023-01-02T15:21:44.630Z [test_server:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000117
[2] 35 (MsgType) = A[Logon], [3] 49 (SenderCompID) = init-comp
[4] 56 (TargetCompID) = accept-comp, [5] 34 (MsgSeqNum) = 2
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:21:44.628
[8] 98 (EncryptMethod) = 0[None], [9] 108 (HeartBtInt) = 30
[10] 141 (ResetSeqNumFlag) = N[No], [11] 553 (Username) = js-client
[12] 554 (Password) = pwd-client, [13] 10 (CheckSum) = 017
2023-01-02T15:21:44.630Z [test_server:FixSession] info: peerLogon Username = js-client, heartBtInt = 30, peerCompId = init-comp, userName = js-client
2023-01-02T15:21:44.630Z [test_server] info: peer logs in user js-client
2023-01-02T15:21:44.630Z [test_server:FixSession] info: peerLogon onLogon returns true
2023-01-02T15:21:44.630Z [test_server:FixSession] info: current state WaitingForALogon (18) moves to InitiationLogonResponse (9)
2023-01-02T15:21:44.630Z [test_server:FixSession] info: acceptor responds to logon request
2023-01-02T15:21:44.631Z [test_server:FixSession] info: start heartbeat timer. interval = 200
2023-01-02T15:21:44.631Z [test_server:FixSession] info: system ready, inform app
2023-01-02T15:21:44.631Z [test_server] info: onReady
2023-01-02T15:21:44.631Z [test_server] info: acceptor is ready for requests
2023-01-02T15:21:44.631Z [test_client:FixSession] info: A: Logon
2023-01-02T15:21:44.631Z [test_client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000117
[2] 35 (MsgType) = A[Logon], [3] 49 (SenderCompID) = accept-comp
[4] 56 (TargetCompID) = init-comp, [5] 34 (MsgSeqNum) = 2
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:21:44.630
[8] 98 (EncryptMethod) = 0[None], [9] 108 (HeartBtInt) = 30
[10] 141 (ResetSeqNumFlag) = N[No], [11] 553 (Username) = js-server
[12] 554 (Password) = pwd-server, [13] 10 (CheckSum) = 058
2023-01-02T15:21:44.631Z [test_client:FixSession] info: peerLogon Username = js-server, heartBtInt = 30, peerCompId = accept-comp, userName = js-server
2023-01-02T15:21:44.631Z [test_client] info: peer logs in user js-server
2023-01-02T15:21:44.631Z [test_client:FixSession] info: peerLogon onLogon returns true
2023-01-02T15:21:44.631Z [test_client:FixSession] info: initiator receives logon response
2023-01-02T15:21:44.632Z [test_client:FixSession] info: current state InitiationLogonSent (7) moves to InitiationLogonReceived (8)
2023-01-02T15:21:44.632Z [test_client:FixSession] info: start heartbeat timer. interval = 200
2023-01-02T15:21:44.632Z [test_client:FixSession] info: system ready, inform app
2023-01-02T15:21:44.632Z [test_client] info: onReady
2023-01-02T15:21:44.632Z [test_client] info: will logout after 45
2023-01-02T15:22:14.796Z [test_client:FixSession] info: 0: Heartbeat
2023-01-02T15:22:14.797Z [test_client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000104
[2] 35 (MsgType) = 0[Heartbeat], [3] 49 (SenderCompID) = accept-comp
[4] 56 (TargetCompID) = init-comp, [5] 34 (MsgSeqNum) = 3
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:22:14.793
[8] 112 (TestReqID) = Mon, 02 Jan 2023 15:22:14 GMT, [9] 10 (CheckSum) = 033
2023-01-02T15:22:14.797Z [test_client:FixSession] info: current state InitiationLogonReceived (8) moves to ActiveNormalSession (17)
2023-01-02T15:22:14.797Z [RespawnAcceptor] info: rxOnMsg msgType = 0
2023-01-02T15:22:14.797Z [test_server:FixSession] info: 0: Heartbeat
2023-01-02T15:22:14.797Z [test_server:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000104
[2] 35 (MsgType) = 0[Heartbeat], [3] 49 (SenderCompID) = init-comp
[4] 56 (TargetCompID) = accept-comp, [5] 34 (MsgSeqNum) = 3
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:22:14.795
[8] 112 (TestReqID) = Mon, 02 Jan 2023 15:22:14 GMT, [9] 10 (CheckSum) = 035
2023-01-02T15:22:14.797Z [test_server:FixSession] info: current state InitiationLogonResponse (9) moves to ActiveNormalSession (17)
2023-01-02T15:22:19.613Z [test_client:FixSession] info: current state ActiveNormalSession (17) moves to WaitingLogoutConfirm (21)
2023-01-02T15:22:19.614Z [test_client:FixSession] info: test_client initiate logout
2023-01-02T15:22:19.615Z [test_client:FixSession] info: sending logout with test_client initiate logout
2023-01-02T15:22:19.616Z [test_client:FixSession] info: done. check logout sequence state WaitingLogoutConfirm
2023-01-02T15:22:19.617Z [RespawnAcceptor] info: rxOnMsg msgType = 5
2023-01-02T15:22:19.617Z [test_server:FixSession] info: 5: Logout
2023-01-02T15:22:19.618Z [test_server:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000075
[2] 35 (MsgType) = 5[Logout], [3] 49 (SenderCompID) = init-comp
[4] 56 (TargetCompID) = accept-comp, [5] 34 (MsgSeqNum) = 4
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:22:19.615
[8] 58 (Text) = 5, [9] 10 (CheckSum) = 119
2023-01-02T15:22:19.618Z [test_server:FixSession] info: current state ActiveNormalSession (17) moves to ConfirmingLogout (22)
2023-01-02T15:22:19.618Z [test_server:FixSession] info: peer initiates logout Text = '5'
2023-01-02T15:22:19.618Z [test_server:FixSession] info: test_server confirming logout
2023-01-02T15:22:19.618Z [test_server:FixSession] info: sending logout with test_server confirming logout
2023-01-02T15:22:19.619Z [test_client:FixSession] info: 5: Logout
2023-01-02T15:22:19.619Z [test_client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 0000075
[2] 35 (MsgType) = 5[Logout], [3] 49 (SenderCompID) = accept-comp
[4] 56 (TargetCompID) = init-comp, [5] 34 (MsgSeqNum) = 4
[6] 57 (TargetSubID) = fix, [7] 52 (SendingTime) = 20230102-15:22:19.618
[8] 58 (Text) = 5, [9] 10 (CheckSum) = 122
2023-01-02T15:22:19.619Z [test_client:FixSession] info: peer confirms logout Text = '5'
2023-01-02T15:22:19.619Z [test_client:FixSession] info: stopTimer
2023-01-02T15:22:19.619Z [test_client:FixSession] info: unsubscribe sessionState = [compId = init-comp, heartBeat = 30, state = WaitingLogoutConfirm (21), nextTickAction = Nothing (1), now = 15:22:19.566, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:22:19.619, LastSentAt = 15:22:19.615, lastTestRequestAt = null, logoutSentAt = 15:22:19.614, peerHeartBeatSecs = 30, peerCompId = accept-comp, lastPeerMsgSeqNum = 4, LastSentSeqNum = 4, secondsSinceLogoutSent = -1, secondsSinceSent = 4.771, secondsSinceReceive = 4.769]
2023-01-02T15:22:19.619Z [test_client:FixSession] info: stop: kill transport
2023-01-02T15:22:19.619Z [test_client:RecoveringTcpInitiator] info: session has permanently ended
2023-01-02T15:22:19.620Z [test_client:TcpInitiator] info: end :state 2
2023-01-02T15:22:19.620Z [test_client:RecoveringTcpInitiator] info: run: transport 0 gracefully ends 60 - resolving
2023-01-02T15:22:19.620Z [test_client:FixSession] info: current state WaitingLogoutConfirm (21) moves to Stopped (23)
2023-01-02T15:22:19.620Z [test_client] info: stopped
2023-01-02T15:22:19.620Z [test_client:TcpInitiator] info: end :state 4
2023-01-02T15:22:19.620Z [test_client:RecoveringTcpInitiator] info: run: transport 0 gracefully ends 60 - resolving
2023-01-02T15:22:19.621Z [test_server:FixSession] info: rx end received sessionState = [compId = accept-comp, heartBeat = 30, state = ConfirmingLogout (22), nextTickAction = Nothing (1), now = 15:22:19.566, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:22:19.618, LastSentAt = 15:22:19.618, lastTestRequestAt = null, logoutSentAt = 15:22:19.618, peerHeartBeatSecs = 30, peerCompId = init-comp, lastPeerMsgSeqNum = 4, LastSentSeqNum = 4, secondsSinceLogoutSent = -1, secondsSinceSent = 4.773, secondsSinceReceive = 4.769]
2023-01-02T15:22:19.621Z [test_server:FixSession] info: rx receives end state = ConfirmingLogout - stop session
2023-01-02T15:22:19.621Z [test_server:FixSession] info: stopTimer
2023-01-02T15:22:19.621Z [test_server:FixSession] info: unsubscribe sessionState = [compId = accept-comp, heartBeat = 30, state = ConfirmingLogout (22), nextTickAction = Nothing (1), now = 15:22:19.566, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:22:19.618, LastSentAt = 15:22:19.618, lastTestRequestAt = null, logoutSentAt = 15:22:19.618, peerHeartBeatSecs = 30, peerCompId = init-comp, lastPeerMsgSeqNum = 4, LastSentSeqNum = 4, secondsSinceLogoutSent = -1, secondsSinceSent = 4.773, secondsSinceReceive = 4.769]
2023-01-02T15:22:19.621Z [test_server:FixSession] info: stop: kill transport
2023-01-02T15:22:19.621Z [test_server:FixSession] info: ignoring request to change state as now already in ConfirmingLogout
2023-01-02T15:22:19.621Z [test_server] info: stopped
2023-01-02T15:22:19.621Z [test_server:TcpAcceptor] info: transport 1 ends total transports = 0
2023-01-02T15:22:19.621Z [test_server:FixSession] info: rx done received
2023-01-02T15:22:19.621Z [test_server:FixSession] info: unsubscribe sessionState = [compId = accept-comp, heartBeat = 30, state = ConfirmingLogout (22), nextTickAction = Nothing (1), now = 15:22:19.566, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:22:19.618, LastSentAt = 15:22:19.618, lastTestRequestAt = null, logoutSentAt = 15:22:19.618, peerHeartBeatSecs = 30, peerCompId = init-comp, lastPeerMsgSeqNum = 4, LastSentSeqNum = 4, secondsSinceLogoutSent = -1, secondsSinceSent = 4.773, secondsSinceReceive = 4.769]
2023-01-02T15:22:19.621Z [test_server:FixSession] info: stop: kill transport
2023-01-02T15:22:19.621Z [test_server:FixSession] info: ignoring request to change state as now already in ConfirmingLogout
2023-01-02T15:22:19.621Z [test_server] info: stopped
2023-01-02T15:22:19.621Z [test_server:FixSession] info: done. check logout sequence state ConfirmingLogout
2023-01-02T15:22:19.622Z [acceptor] info: ends
2023-01-02T15:22:19.622Z [test_server:TcpAcceptor] info: close listener on port 2344
2023-01-02T15:22:19.622Z [acceptor] info: acceptor closed.
2023-01-02T15:22:19.622Z [RespawnAcceptor] info: acceptor respawned reject = 1
2023-01-02T15:22:19.622Z [launcher] error: undefined : undefined
2023-01-02T15:22:19.624Z [test_client:FixSession] info: rx end received sessionState = [compId = init-comp, heartBeat = 30, state = Stopped (23), nextTickAction = Nothing (1), now = 15:22:19.566, timeToDie = false, timeToHeartbeat = false, timeToTerminate = false, timeToTestRequest = false, lastReceivedAt = 15:22:19.619, LastSentAt = 15:22:19.615, lastTestRequestAt = null, logoutSentAt = 15:22:19.614, peerHeartBeatSecs = 30, peerCompId = accept-comp, lastPeerMsgSeqNum = 4, LastSentSeqNum = 4, secondsSinceLogoutSent = -1, secondsSinceSent = 4.771, secondsSinceReceive = 4.769]
2023-01-02T15:22:19.624Z [test_client:FixSession] info: rx receives end state = Stopped - stop session
2023-01-02T15:22:19.624Z [test_client:FixSession] info: rx done received
2023-01-02T15:22:19.624Z [test_client:FixSession] info: done. session is now stopped
2023-01-02T15:22:19.624Z [test_client:FixSession] info: done. check logout sequence state Stopped
2023-01-02T15:22:29.631Z [test_client:FixSession] info: done. session is now stopped
2023-01-02T15:22:29.632Z [test_client:FixSession] info: done. check logout sequence state Stopped
TimelordUK commented 8 months ago

this seems to be resolved, thanks raising closing