unexpected state: about jspf-demo HOT 16 CLOSED

from jspf-demo.

received the same with additional log line:
2021-12-05T17:54:45.749Z [lightTrader - client:TcpInitiator] info: tlsDuplex resolving
(new packages, using below package.json)

Is client:FixSession expecting a particular message after the auth'd logon? The version i use from source is older and maybe you've added more checks to fix-session recently??

{
"name": "pitt",
"version": "1.0.0",
"description": "blah",
"main": "dist/app.js",
"types": "dist/index.d.ts",
"scripts": {
"test": "echo "Error: no test specified" && exit 1"
},
"author": "lT",
"license": "ISC",
"dependencies": {
"jspurefix": "^1.4.1",
"request": "^2.88.2",
"typings": "^2.1.1",
"path": "^0.12.7"
},
"devDependencies": {
"@types/lodash": "^4.14.177",
"@types/node": "^16.11.11",
"@types/sax": "^1.2.3",
"standard": "^16.0.4",
"ts-jest": "^27.1.0",
"tslint": "^6.0.0",
"tslint-config-standard": "^9.0.0",
"typescript": "^4.5.2"
}
}

from jspf-demo.

2021-12-05T17:08:43.899Z [lightTrader - client:TcpInitiator] info: tryConnect workingServer.com:443

is that port 443 remote connection, are you connecting on SSL?

from jspf-demo.

yes -

const socket = tls.connect(tcp.port, tcp.host, options, () => {}

my source version has this working method in fix-session:-

// try to connect to the server
private tryConnect(): Promise {
const options = {
cert: fs.readFileSync(this.clientCert.cert),
key: fs.readFileSync(this.clientCert.key),
};
return new Promise((resolve, reject) => {
const tcp = this.tcp;
this.logger.info(tryConnectSSL ${tcp.host}:${tcp.port});
const socket = tls.connect(tcp.port, tcp.host, options, () => {
if (socket.authorized) {
this.logger.info("Auth success, connected to this TLS server");
this.duplex = new TcpDuplex(socket);
resolve(new MsgTransport(0, this.jsFixConfig, this.duplex));
} else {
//Something may be wrong with your certificates
this.logger.info("Failed to auth TLS connection: ");
this.logger.info(socket.authorizationError.message);
}
});
socket.on("error", (e) => {
reject(e);
});
});

from jspf-demo.

it looks from the log that we do not even receive a response- ie. when we send the login we then see the connection go down, can you see your login request in fix log, the remote connection looks like they are dropping connection immediately have we definately got right credentials in message.

This log error is saying transport has gone down when we did not expect i.e. the remote server seems to have taken it down rather than us sending logout and getting logout confirm

from jspf-demo.

i'm using the same credentials with the method above and it stays up, i'll check with the server - now

from jspf-demo.

if i look in a test TLS session I see

2021-12-05T18:29:39.400Z [test_client:TcpInitiator] info: client connected authorized
2021-12-05T18:29:39.401Z [test_client:TcpInitiator] info: enabling tls session trace
2021-12-05T18:29:39.402Z [test_client:TcpInitiator] info: tlsDuplex resolving
2021-12-05T18:29:39.411Z [initiator] info: ... connected, run session

do you see this sequence - there may be an issue in the initiator unfortunately I do not have a commercial TLS end point I can connect too.

2021-12-05T18:29:39.411Z [initiator] info: ... connected, run session
Sent Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 175
Inner Content Type = ApplicationData (23)

from jspf-demo.

i see we now set tlsSocket.setEncoding('utf8') ....

one thing you can do is rather than install from npm install src from git

cd node_modules
git clone https://github.com/TimelordUK/jspurefix .
cd jspurefix
npm install

then run you application- then we can change tcp-initiator,

recompile

cd jspurefix
node_modules/jspurefix/.bin/tsc

and see if we can diagnose issue

from jspf-demo.

i copied the initator exactly from my source version removing the line (not present on my other version)

"TargetSubID": "fix",

seems to have resolved the logon - have you seen this as a required field before??

(btw, yes this is a comercial TLS endpoint that's dropping the connection with that field, after successful auth & handshake)

from jspf-demo.

But now ! Are you sure your changes made it into the npm version??

2021-12-05T19:42:12.535Z [lightTrader - client:FixSession] info: peerLogon onLogon returns true
2021-12-05T19:42:12.536Z [lightTrader - client:FixSession] info: initiator receives logon response
2021-12-05T19:42:12.536Z [lightTrader - client:FixSession] info: current state InitiationLogonSent (7) moves to InitiationLogonReceived (8)
2021-12-05T19:42:12.536Z [lightTrader - client:FixSession] info: system ready, inform app
2021-12-05T19:42:12.536Z [lightTrader - client:TradeCaptureClient] info: ready
2021-12-05T19:42:12.537Z [lightTrader - client:TradeCaptureClient] info: will logout after 32
2021-12-05T19:42:12.539Z [lightTrader - client:FixSession] warn: tx error event: expected array instance for group NoDates Error: expected array instance for group NoDates
at AsciiEncoder.encodeInstances (/pitt/node_modules/jspurefix/dist/buffer/ascii/ascii-encoder.js:85:19)
at Object.group (/pitt/node_modules/jspurefix/dist/buffer/ascii/ascii-encoder.js:61:22)
at dispatchField (/pitt/node_modules/jspurefix/dist/dictionary/fields-dispatch.js:9:28)
at /born/pitt/node_modules/jspurefix/dist/dictionary/fields-dispatch.js:36:9
at Array.forEach ()
at Object.dispatchFields (/pitt/node_modules/jspurefix/dist/dictionary/fields-dispatch.js:35:12)
at

Via:-

public static getTcrWith2Dates(
requestId: string,
tradeDate1: Date,
tradeDate2: Date
): ITradeCaptureReportRequest {
const tcr = {
TradeRequestID: requestId,
TradeRequestType: TradeRequestType.MatchedTradesMatchingCriteria,
SubscriptionRequestType: SubscriptionRequestType.SnapshotAndUpdates,
TrdCapDtGrp: {
NoDates: [
{
TransactTime: tradeDate1,
},
{
TransactTime: tradeDate2,
},
] as ITrdCapDtGrpNoDates[],
},
} as any // ITradeCaptureReportRequest
return tcr
}

(this type is not allowed as ITradeCaptureReportRequest)

from jspf-demo.

from jspf-demo.

import {
OrdStatus,
SubscriptionRequestType,
TradeReportType,
TradeRequestResult,
TradeRequestStatus,
TradeRequestType,
TrdType,
ITradeCaptureReport,
ITradeCaptureReportRequestAck,
} from 'jspurefix/dist/types/FIX4.4/repo'

import { TradeReportTransType } from 'jspurefix/dist/types/FIXML50SP2/enum/all-enum'

import { ITrdCapDtGrpNoDates, ITradeCaptureReportRequest } from 'jspurefix/dist/types/FIX4.4/quickfix'

from jspf-demo.

this code :-

public static getTcrWith2Dates(
requestId: string,
tradeDate1: Date,
tradeDate2: Date
): ITradeCaptureReportRequest {
const tcr = {
TradeRequestID: requestId,
TradeRequestType: TradeRequestType.MatchedTradesMatchingCriteria,
SubscriptionRequestType: SubscriptionRequestType.SnapshotAndUpdates,
TrdCapDtGrp: {
NoDates: [
{
TransactTime: tradeDate1,
},
{
TransactTime: tradeDate2,
},
] as ITrdCapDtGrpNoDates[],
},
} as ITradeCaptureReportRequest
return tcr
}

gives:-

2021-12-05T20:14:00.736Z [lightTrader - client:FixSession] warn: tx error event: expected array instance for group NoDates Error: expected array instance for group NoDates
at AsciiEncoder.encodeInstances (/born/pitt/node_modules/jspurefix/dist/buffer/ascii/ascii-encoder.js:85:19)

from jspf-demo.

from jspf-demo.

i'm loading
"protocol": "ascii",
"dictionary": "repo44"
will change and try data/FIX44.xml

from jspf-demo.

Eureka! Many thanks for your efforts on this.. your call whether you remove the "TargetSubID": "fix" and change the dictionary to data/FIX44.xml for 2 dates in the demo

Expected output:-

2021-12-05T20:19:13.712Z [launcher] info: launching ..
2021-12-05T20:19:14.844Z [launcher] info: create initiator
2021-12-05T20:19:14.845Z [initiator] info: create session
2021-12-05T20:19:14.853Z [initiator] info: connecting ...
2021-12-05T20:19:14.854Z [lightTrader - client:TcpInitiator] info: connecting with timeout 22
2021-12-05T20:19:14.871Z [lightTrader - client:TcpInitiator] info: tryConnect fix.lmaxtrader.com:443
2021-12-05T20:19:14.871Z [launcher] info: launching ....
2021-12-05T20:19:14.910Z [lightTrader - client:TcpInitiator] info: client connected authorized
2021-12-05T20:19:14.911Z [lightTrader - client:TcpInitiator] info: tlsDuplex resolving
2021-12-05T20:19:14.913Z [initiator] info: ... connected, run session
2021-12-05T20:19:14.918Z [lightTrader - client:FixSession] info: current state Idle (24) moves to InitiationLogonSent (7)
2021-12-05T20:19:14.952Z [lightTrader - client:FixSession] info: A: Logon
2021-12-05T20:19:14.953Z [lightTrader - client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 81
[2] 35 (MsgType) = A[Logon], [3] 49 (SenderCompID) = QWERTY0
[4] 56 (TargetCompID) = lightTraderComp, [5] 34 (MsgSeqNum) = 1
[6] 52 (SendingTime) = 20211205-20:19:14.946, [7] 98 (EncryptMethod) = 0[None]
[8] 108 (HeartBtInt) = 30, [9] 141 (ResetSeqNumFlag) = Y[Yes]
[10] 10 (CheckSum) = 097
2021-12-05T20:19:14.954Z [lightTrader - client:FixSession] info: peerLogon Username = undefined, heartBtInt = 30, peerCompId = QWERTY0, userName = undefined
2021-12-05T20:19:14.954Z [lightTrader - client:FixSession] info: peerLogon onLogon returns true
2021-12-05T20:19:14.954Z [lightTrader - client:FixSession] info: initiator receives logon response
2021-12-05T20:19:14.954Z [lightTrader - client:FixSession] info: current state InitiationLogonSent (7) moves to InitiationLogonReceived (8)
2021-12-05T20:19:14.954Z [lightTrader - client:FixSession] info: system ready, inform app
2021-12-05T20:19:14.954Z [lightTrader - client:TradeCaptureClient] info: ready
2021-12-05T20:19:14.956Z [lightTrader - client:TradeCaptureClient] info: will logout after 32
2021-12-05T20:19:15.058Z [lightTrader - client:FixSession] info: AQ: TradeCaptureReportRequestAck
2021-12-05T20:19:15.058Z [lightTrader - client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 103
[2] 35 (MsgType) = AQ[TradeCaptureReportRequestAck], [3] 49 (SenderCompID) = QWERTY0
[4] 56 (TargetCompID) = lightTraderComp, [5] 34 (MsgSeqNum) = 2
[6] 52 (SendingTime) = 20211205-20:19:15.053, [7] 568 (TradeRequestID) = all-trades
[8] 569 (TradeRequestType) = 1[MatchedTradesMatchingCriteriaProvidedOnRequest], [9] 263 (SubscriptionRequestType) = 0[Snapshot]
[10] 749 (TradeRequestResult) = 0[Successful], [11] 750 (TradeRequestStatus) = 0[Accepted]
[12] 10 (CheckSum) = 144
2021-12-05T20:19:15.058Z [lightTrader - client:FixSession] info: ascii forwarding msgType = 'AQ' to application
2021-12-05T20:19:15.059Z [lightTrader - client:FixSession] info: current state InitiationLogonReceived (8) moves to ActiveNormalSession (17)
2021-12-05T20:19:15.060Z [lightTrader - client:TradeCaptureClient] info: {
"StandardHeader": {
"BeginString": "FIX.4.4",
"BodyLength": 103,
"MsgType": "AQ",
"SenderCompID": "QWERTY0",
"TargetCompID": "lightTraderComp",
"MsgSeqNum": 2,
"SendingTime": "2021-12-05T20:19:15.053Z"
},
"TradeRequestID": "all-trades",
"TradeRequestType": 1,
"SubscriptionRequestType": "0",
"TradeRequestResult": 0,
"TradeRequestStatus": 0,
"StandardTrailer": {
"CheckSum": "144"
}
}
2021-12-05T20:19:15.060Z [lightTrader - client:TradeCaptureClient] info: received tcr ack all-trades 0
2021-12-05T20:19:15.061Z [lightTrader - client:FixSession] info: AE: TradeCaptureReport
2021-12-05T20:19:15.062Z [lightTrader - client:FixSession] info: [0] 8 (BeginString) = FIX.4.4, [1] 9 (BodyLength) = 248
[2] 35 (MsgType) = AE[TradeCaptureReport], [3] 49 (SenderCompID) = QWERTY0
[4] 56 (TargetCompID) = lightTraderComp, [5] 34 (MsgSeqNum) = 3
[6] 52 (SendingTime) = 20211205-20:19:15.054, [7] 568 (TradeRequestID) = all-trades
[8] 912 (LastRptRequested) = N, [9] 17 (ExecID) = cdzY2gAAAAS1wgy3
[10] 527 (SecondaryExecID) = QGESGAAAAS02EDFW, [11] 48 (SecurityID) = 4004
[12] 22 (SecurityIDSource) = 8[ExchangeSymbol], [13] 32 (LastQty) = 1.9
[14] 31 (LastPx) = 113.25, [15] 75 (TradeDate) = 20211129
[16] 60 (TransactTime) = 20211129-05:57:39.389, [17] 552 (NoSides) = 1[OneSide]
[18] 54 (Side) = 1[Buy], [19] 37 (OrderID) = AAGJIwAAAANjKj7K
[20] 11 (ClOrdID) = 208.001, [21] 1 (Account) = 1910298842
[22] 10 (CheckSum) = 215
2021-12-05T20:19:15.062Z [lightTrader - client:FixSession] info: ascii forwarding msgType = 'AE' to application
2021-12-05T20:19:15.063Z [lightTrader - client:TradeCaptureClient] info: {
"StandardHeader": {
"BeginString": "FIX.4.4",
"BodyLength": 248,
"MsgType": "AE",
"SenderCompID": "QWERTY0",
"TargetCompID": "lightTraderComp",
"MsgSeqNum": 3,
"SendingTime": "2021-12-05T20:19:15.054Z"
},
"TradeRequestID": "all-trades",
"LastRptRequested": false,
"ExecID": "cdzY2gAAAAS1wgy3",
"SecondaryExecID": "QGESGAAAAS02EDFW",
"Instrument": {
"SecurityID": "12345",
"SecurityIDSource": "8"
},
"LastQty": 1.9,
"LastPx": 113.25,
"TradeDate": "2021-11-29T00:00:00.000Z",
"TransactTime": "2021-11-29T05:57:39.389Z",
"TrdCapRptSideGrp": {
"NoSides": [
{
"Side": "1",
"OrderID": "AAGJIwAAAANjKj7K",
"ClOrdID": "208.001",
"Account": "1910298842"
}
]
},
"StandardTrailer": {
"CheckSum": "215"
}
}

from jspf-demo.