Tracking messages across the Platform

In this tutorial we shall consider an incident in which data is sent across the platform which is suspected to be incorrect. You will use the log files to track the data messages across the trading system, from the client to the price server.

Use the test page to request prices for JPYUSD. You will notice that the price updates for this currency pair appear suspicious with the BidPrice and AskPrice being in the range of 0.012 at times and 120 at others.

It is possible that the data being transferred is altered some way along the line. This could happen if there are renderers on your client application which are altering the data, data is incorrectly altered by some module in Transformer, the Pricing Adapter is doing some incorrect processing before sending price updates or data is corrupt during transfer.

The only way to find out what the problem is to trace the message through the logs at each stage.

SLJS Messages vs Client Display

The first place to look for errors is in the client application. Is it displaying the values which it actually receives from Liberator (via StreamLink), or is it altering them in some way before display?

Follow the steps below:

  1. Add the URL parameter debug=finer to the test page URL and reload the page. (You need to enable pop-ups in the browser.) Using this parameter will bring up the StreamLink logs in a separate browser window once you initiate a StreamLink connection. (The same URL parameter is used to bring up StreamLink logs in a Caplin Trader client application.)

  2. When you connect and make the subscription, you will notice the following log lines. The third line is the actual request message sent to Liberator.

    <timestamp> - INFO : StreamLink subscribe /FX/JPYUSD called.
<timestamp> - FINE : Out - Request [subject=/FX/JPYUSD, parameters=SubscriptionParameters [fields=, filter=, imageFilter=]]
<timestamp> - FINER : > <session-id>+REQUEST+%252FFX%252FJPYUSD

    Can you spot the corresponding request logged on the Liberator logs? Hint: The session id is that which appears in the StreamLink request message.

  3. Consider tracking an update for which BidPrice = 127.74036 and AskPrice = 127.77461. The corresponding message in the StreamLink logs will appear in the following format:

    2013/09/20-15:33:23.771 +0100 - FINER  : < 6c070002 G=1380378798768 H=trans_E%2Ctrans_X%2Clib_E I=5001%2C5001%2C5002 L=/FX/JPYUSD M=127.74036 N=127.77461 O=JPY/USD_TIER1_S_15:33:18.638_12 P=JPY/USD_TIER1_S_15:33:18.640_15 Q=1000000.0 R=1000000.0 S=1380378798768
2013/09/20-15:33:23.771 +0100 - FINE   : In - RecordType1DataEvent [subject=/FX/JPYUSD, fields=[LTY_INIT_TS=1380378798768,LTY_LIST_EVENT=trans_E,trans_X,lib_E,LTY_LIST_TS=5001,5001,5002,InstrumentName=/FX/JPYUSD,BidPrice=127.74036,AskPrice=127.77461,BidPriceId=JPY/USD_TIER1_S_15:33:18.638_12,AskPriceId=JPY/USD_TIER1_S_15:33:18.640_15,BidGFA=1000000.0,AskGFA=1000000.0,Timestamp=1380378798768], image=false, timeReceived=1380378803771]

    The first log line is the actual StreamLink message received. The second log line shows the message as it has been decoded by the StreamLink API.

The anatomy of the raw StreamLink message is as follows:

  • The first 2 characters (6c) are the RTTP code indicating the type of message. There is a two character code for every type of message - e.g. "1b" is login+ok, "6c" is a record update, etc.

  • The next 2 characters (07) are the sequence number. You’ll notice that this increases by one with each message: 07, 08, 09 etc. It is used for reconnection, enabling the Liberator to resume sending messages to the client from the right point.

  • The next 4 characters (0002) are the object subscription number. This is a four digit code that is assigned by Liberator when the client requests an object. The actual assignment of the number is not shown in your log snippet, it happens as a response to the client request. It basically just maps the object name (which might be very long) to a unique four character code that identifies the subscription.

  • The rest of the message is the fields. When the client logs in, Liberator will send a large message called the field map which maps every field name to a number, e.g.:

    <timestamp> - FINER : < 0o 1=CONTRIB_USER 2=KEY ... L=InstrumentName M=BidPrice N=AskPrice O=BidPriceId ...

These logs prove that the data being displayed on the client, is in fact the same as the data received over the network from Liberator, therefore these logs eliminate the possibility that the prices are being altered by the test client

Liberator RTTP Messages vs Client SLJS

The next thing we must check is whether the data is being altered in some way over the network.

Follow the steps below:

  1. The communication between Liberator and its client applications is logged in RTTP message logs. You are required to turn on RTTP message logging on Liberator, as these logs are not generated by default. (RTTP traffic logs can become very large very quickly.)

    Add the following configuration in global_config/overrides/servers/Liberator/etc/rttpd.conf:

    rttp-log
rttp-log-users admin

  2. Create a new folder named "rttp" in the log’s directory "var". A log file will be created in this folder for each user session, and named accordingly.

  3. The logs in the session’s RTTP message log show the raw StreamLink messages being sent by Liberator, and they are in the same format as the StreamLink logs on the client application. Use the "grep" command to filter the log using a unique field’s value (such as the BidPriceId) and isolate a price update. Compare this to the StreamLink messages on the client. Do the messages sent from Liberator correspond to those received by the StreamLink client?

Liberator vs Transformer Messages

Liberator routes all FX price requests through Transformer, therefore price updates are received from Transformer. In order to ensure that the data is not altered by Liberator, we must ensure that the data received from Transformer is that which is sent to the client. Since Transformer is a peer DataSource application, the communication between it and Liberator is logged in the Liberator packet log.

Try this yourself

Open Liberator’s packet log and compare the logs here with the corresponding log message in the RTTP message log

Transformer vs Pricing Adapter Messages

Is there some module in Transformer which is altering the data before propagating it to Liberator?

The Transformer packet log shows the messages received from the Pricing Adapter and sent to Liberator. Those of the Pricing Adapter show the messages sent to Transformer.

Compare Transformer’s packet log to the Pricing Adapter’s packet log. You can open the adapter’s packet log using the following command:

./servers/Liberator/bin/logcat.exe kits/PricingAdapter/PricingAdapter-<version>/var/packet-PricingAdapter.log

Pricing Adapter vs Pricing Server

Finally, is the Pricing Integration Adapter sending the same data which the Pricing Server is producing? Or is it altering the prices before sending them on? To determine this you need to compare the messages in the adapter’s packet log to the logs produced by the pricing server. (The format of these logs, of course, varies depending on the pricing server used.) For the SimpleFXServer the log files can be found in the console output of the running server, and in the "var" directory which was automatically created in the folder where your server (jar) is located.

Review

Having followed this tutorial, you should have determined that the anomalous JPYUSD prices are in fact originating at the server, and are not the result of manipulation by some platform component, the client application or corruption over the network. The trace followed is:

  1. On the client display:

    Instrument: /FX/JPYUSD, BidPrice=127.74036, AskPrice=127.77461

  2. The StreamLink logs on the client show that the data received from Liberator over the network is the same as the data displayed:

    2013/09/20-15:33:23.771 +0100 - FINER  : < 6c070002 G=1380378798768 H=trans_E%2Ctrans_X%2Clib_E I=5001%2C5001%2C5002 L=/FX/JPYUSD M=127.74036 N=127.77461 O=JPY/USD_TIER1_S_15:33:18.638_12 P=JPY/USD_TIER1_S_15:33:18.640_15 Q=1000000.0 R=1000000.0 S=1380378798768
2013/09/20-15:33:23.771 +0100 - FINE   : In - RecordType1DataEvent [subject=/FX/JPYUSD, fields=[LTY_INIT_TS=1380378798768,LTY_LIST_EVENT=trans_E,trans_X,lib_E,LTY_LIST_TS=5001,5001,5002,InstrumentName=/FX/JPYUSD,BidPrice=127.74036,AskPrice=127.77461,BidPriceId=JPY/USD_TIER1_S_15:33:18.638_12,AskPriceId=JPY/USD_TIER1_S_15:33:18.640_15,BidGFA=1000000.0,AskGFA=1000000.0,Timestamp=1380378798768], image=false, timeReceived=1380378803771]

  3. The RTTP message logs on Liberator show that the data being sent over the network by Liberator, is in fact, the same as that received by the client:

    >>> 20 Sep 15:33:23.77
6c070002 G=1380378798768 H=trans_E%2Ctrans_X%2Clib_E I=5001%2C5001%2C5002 L=/FX/JPYUSD M=127.74036 N=127.77461 O=JPY/USD_TIER1_S_15:33:18.638_12 P=JPY/USD_TIER1_S_15:33:18.640_15 Q=1000000.0 R=1000000.0 S=1380378798768

  4. Examining Liberator’s packet logs shows that the data received from Transformer (peer id: 102) is that whic Liberator sent to the client:

    2013/09/20-15:33:23.770 +0100: 127.0.0.1 < DATAUPDATE2 102 5 48 /FX/JPYUSD 222 11 -45028=/FX/JPYUSD -45029=127.74036 -45030=127.77461 -45031=JPY/USD_TIER1_S_15:33:18.638_12 -45032=JPY/USD_TIER1_S_15:33:18.640_15 -45033=1000000.0 -45034=1000000.0 -45035=1380378798768 -10302=1380378798768 -10303=trans_E,trans_X -10304=5001,5001

  5. Transformer’s packet log revels that the data sent to Liberator (peer id: 101) is the same as that received by Liberator (above) and the same as the data received from the Pricing Adapter (peer id: 1917):

    2013/09/20-15:33:23.769 +0100: 127.0.0.1 < DATAUPDATE2 1917 3 48 /FX/JPYUSD 222 9 -45028=/FX/JPYUSD -45029=127.74036 -45030=127.77461 -45031=JPY/USD_TIER1_S_15:33:18.638_12 -45032=JPY/USD_TIER1_S_15:33:18.640_15 -45033=1000000.0 -45034=1000000.0 -45035=1380378798768 -10302=1380378798768
2013/09/20-15:33:23.769 +0100: 127.0.0.1 > DATAUPDATE2 101 5 48 /FX/JPYUSD 222 11 -45028=/FX/JPYUSD -45029=127.74036 -45030=127.77461 -45031=JPY/USD_TIER1_S_15:33:18.638_12 -45032=JPY/USD_TIER1_S_15:33:18.640_15 -45033=1000000.0 -45034=1000000.0 -45035=1380378798768 -10302=1380378798768 -10303=trans_E,trans_X -10304=5001,5001

  6. The Pricing Adapter’s packet log also shows that it is sending the same data to Transformer:

    2013/09/20-15:33:23.771 +0100: 127.0.0.1 > DATAUPDATE2 102 3 48 /FX/JPYUSD 222 9 -45028=/FX/JPYUSD -45029=127.74036 -45030=127.77461 -45031=JPY/USD_TIER1_S_15:33:18.638_12 -45032=JPY/USD_TIER1_S_15:33:18.640_15 -45033=1000000.0 -45034=1000000.0 -45035=1380378798768 -10302=1380378798768

  7. Finally the Pricing Server’s logs (from the console output) show the same price being sent from the server, allowing us to conclude that the erroneous price is, in fact, produced by the server itself:

    15:33:18,637 INFO  pricing.StaticSeededPriceGenerator  - PriceGeneratorImpl getting price=127.74 for symbol=JPY/USD
15:33:18,643 INFO  pricing.IntervalTaskUpdate  - interval update PREPARING a Subscription Full Refresh (MarketDataSnapshotFullRefresh) MESSAGE
15:33:18,645 INFO  server.GradFIXApplication  - toApp: [sessionID = FIX.4.4:CAPLIN_FIX_RATES1->FIXCLIENT]
15:33:18,647 INFO  server.GradFIXApplication  - toApp: [Message Type = Subscription Full Refresh (MarketDataSnapshotFullRefresh)]
15:33:18,651 INFO  pricing.IntervalTaskUpdate  - interval update SENT: Subscription Full Refresh (MarketDataSnapshotFullRefresh) to sessionID=FIX.4.4:CAPLIN_FIX_RATES1->FIXCLIENT