Interpreting log files

Each of the components in the Caplin Platform produces its own set of log files. In this tutorial you will take a quick look at the main log files on Liberator and Transformer.

You may wish to restart the Caplin Platform and clear the logs before proceeding with this tutorial.

User Authentication & Authorisation

Logs about user authentication and authorisation are written to Liberator’s auth-rttpd.log file. Open the log file with command tail -f servers/Liberator/var/auth-rttpd.log and carry out the following set of steps, observing the log output as you go along:

Follow the steps below:

  1. Use the test client to attempt to connect to Liberator as "user1", but using an incorrect password (e.g. "password2"). Notice that the Java auth module first attempts to check the user credentials against the Java Permissioning Integration Adapter, and then displays the result.

    <timestamp>: INFO: Thread [Thread-6/25]: javaauth : checkUser: sessionId=0JcBmV60xJP0dESP8NhWkb, userName=user1, password=password2
<timestamp>: INFO: Thread [Thread-6/25]: Invalid password password2 for user user1
<timestamp>: INFO: Thread [Thread-6/25]: User login attempt: name=user1 result=Authentication result: Failure: Invalid Password
<timestamp>: INFO: Thread [Thread-6/25]: javaauth : checkUser: sessionId=0JcBmV60xJP0dESP8NhWkb, userName=user1, password=password2: Authentication result: Failure: Invalid Password

  2. Now, connect to Liberator as user1, using the correct password (password1). This time authentication of the user succeeds.

    <timestamp>: INFO: Thread [Thread-6/25]: javaauth : checkUser: sessionId=0HSGzWkO-MEmLhlPKrClVO, userName=user1, password=password1
<timestamp>: INFO: Thread [Thread-6/25]: User login attempt: name=user1 result=Authentication result: Success: OK
<timestamp>: INFO: Thread [Thread-6/25]: javaauth : checkUser: sessionId=0HSGzWkO-MEmLhlPKrClVO, userName=user1, password=password1: Authentication result: Success: OK

  3. Subscribe to subject /FX/GBPUSD. The Permissioning Integration Adapter explicitly specifies that user1 is allowed to see all currencies where base currency is GBP. Therefore the Liberator auth module allows this request.

    <timestamp>: INFO: Thread [Thread-6/25]: ALLOW found in user1: user user1 action VIEW in namespace null for product /FX/GBPUSD

  4. Subscribe to subject /FX/AUDUSD. You will notice that nothing new appears in the auth-rttpd.log file. This is because the Permissioning Adapter does not specify whether or not user1 can subscribe to this currency pair. When this is the case, the Liberator auth module does not authorise this subscription.

  5. How does the Liberator auth module know about the Permissions in the Permissioning Integration Adapter? When Liberator starts up, it automatically subscribes to the authentication and authorisation information, which is returned by the Permissioning Adapter. The messages received from the adapter are delineated by "start" and "commit" messages. This is because permissions are recorded on the Liberator auth module as a sequence of transactions. Take a look inside the packet-rttpd.log file. This is a binary file so open it using command ./servers/Liberator/bin/logcat.exe servers/Liberator/var/packet-rttpd.log.

    1. A transaction is started and a "clear" is received, clearing all existing permissions on the Liberator auth module. The permissions for the admin user are committed:

      <timestamp>: 127.0.0.1 < DATAUPDATE2 1166 0 12592 /PERMISSIONS/MASTER/CONTROL/START 230 2 1=TXN_ID 30012=1
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 1 12592 /PERMISSIONS/MASTER/CONTROL/CLEAR 230 2 1=TIMESTAMP 30005=1380193181254
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 5 12592 /PERMISSIONS/MASTER/USER/admin 230 5 1=PASSWORD 30002=admin 30001=PASSWORD 30003= 30009=
...
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 9 12592 /PERMISSIONS/MASTER/CONTROL/COMMIT 230 2 1=TXN_ID 30012=1
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 10 12336 /PERMISSIONS/MASTER/CONTAINER/admin 228 4 1=/PERMISSIONS/MASTER/CONTROL/CLEAR 1=/PERMISSIONS/MASTER/CONTROL/START 1=/PERMISSIONS/MASTER/USER/admin 1=/PERMISSIONS/MASTER/CONTROL/COMMIT

    2. Next, another transaction is started to submit the permissions for user1. This time it is not preceded by a "clear", so it adds/updates (rather than replaces) the permissions on the Liberator auth module. The permissions submitted are to allow subscriptions (VIEW) of all /FX/GBP* subjects, and private trade messages on the channel /PRIVATE/%U/TRADE/FX (where %U is the unique session username). There is also a FX-ESP-TRADE permission allowing user1 to preform ESP trades on al /FX/GBP* currency pairs:

      <timestamp>: 127.0.0.1 < DATAUPDATE2 1166 11 12592 /PERMISSIONS/MASTER/CONTROL/START 230 2 1=TXN_ID 30012=2
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 12 12592 /PERMISSIONS/MASTER/USER/user1 230 5 1=PASSWORD 30002=password1 30001=PASSWORD 30003= 30009=
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 13 8496 /PERMISSIONS/MASTER/USER/user1 230 5 1=PERMISSION:/FX/GBP.*: 30002=/FX/GBP.* 30001=PERMISSION 30003=VIEW~ALLOW,FX-ESP-TRADE~ALLOW 30009=
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 14 8496 /PERMISSIONS/MASTER/USER/user1 230 5 1=PERMISSION:/PRIVATE/%U/TRADE/FX: 30002=/PRIVATE/%U/TRADE/FX 30001=PERMISSION 30003=VIEW~ALLOW 30009=
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 15 8496 /PERMISSIONS/MASTER/USER/user1 230 5 1=SUBJECT_MAPPER 30002=com.caplin.permissioning.RegexSuffixSubjectMapper 30001=SUBJECT_MAPPER 30003= 30009=
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 16 8496 /PERMISSIONS/MASTER/USER/user1 230 5 1=ROW_COUNT 30002=4 30001=ROW_COUNT 30003= 30009=
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 17 12592 /PERMISSIONS/MASTER/CONTROL/COMMIT 230 2 1=TXN_ID 30012=2
<timestamp>: 127.0.0.1 < DATAUPDATE2 1166 18 12336 /PERMISSIONS/MASTER/CONTAINER/user1 228 4 1=/PERMISSIONS/MASTER/CONTROL/CLEAR 1=/PERMISSIONS/MASTER/CONTROL/START 1=/PERMISSIONS/MASTER/USER/user1 1=/PERMISSIONS/MASTER/CONTROL/COMMIT

Observe the auth-rttpd.log files when you try to execute trades on GBPUSD and AUDUSD. Notice that before displaying authorisation (if any) the logs illustrate that the trade message was matched with a custom permission action (FX-ESP-TRADE) which defines what action the client is trying to accomplish from the fields in the message. This was not done in the case of subscriptions as VIEW is a default action, unlike FX-ESP-TRADE which is an action rule defined programmatically in the Permissioning Adapter.

User Sessions

Follow the steps below:

  1. User sessions can be observed in the session-rttpd.log file. Open the test client in a new browser tab and log in as "user1". You will see that a new user session is opened and is given a unique session id. Next, the log file indicates that the user attempting to log in on that user session was authorised. (Format: TIMESTAMP IP-ADDRESS SESSION-TYPE MSG-TYPE USERNAME APPLICATION-ID SESSION-ID REASON [EXTRA])

    <timestamp>: 127.0.0.1 8 OPEN 0QhsO3rcV4lrbVBW2RyS27
<timestamp>: 127.0.0.1 8 LOGIN_OK admin SLJS 0QhsO3rcV4lrbVBW2RyS27 LOGIN_OK

  2. When you disconnect using the test client, the session connection is lost, and the session is then closed by Liberator 1 minute after the connection is lost.

    <timestamp>: 127.0.0.1 8 LOST admin SLJS 0QhsO3rcV4lrbVBW2RyS27 CLOSE_TYPE2
<timestamp>: 127.0.0.1 8 CLOSE admin SLJS 0QhsO3rcV4lrbVBW2RyS27 TIMEOUT

Try this yourself

Open the test page in several tabs and connect to Liberator from each. Notice that the user can have several unique sessions open at the same time. Notice from auth log that the user is given a unique username (e.g. user1-0, user1-1, user1-2) for each session.

Object Subscriptions

Follow the steps below:

  1. Use the test page to subscribe to a subject, eg. /FX/GBPUSD

  2. The request-rttpd.log file indicates the requests made by each user connected to Liberator. (The request for /PRIVATE/TRADE/FX is made earlier on when the client first connects to Liberator. Each trading client must request this trading subject before being able to trade by publishing trade messages on this subject.)

    [Format: TIMESTAMP IP-ADDRESS USERNAME SESSION-ID MESSAGE]

    <timestamp>: 127.0.0.1 user1 09IP3MJ6d-kXiF-Zra42Ie "09IP3MJ6d-kXiF-Zra42Ie REQUEST /PRIVATE/TRADE/FX"
<timestamp>: 127.0.0.1 user1 09IP3MJ6d-kXiF-Zra42Ie "09IP3MJ6d-kXiF-Zra42Ie REQUEST /FX/GBPUSD"

  3. When the request is made, Liberator creates the objects in memory and searches for peer DataSource applications providing that data. If the Pricing Adapter is running, the event-rttpd.log file will indicate that the object has changed status to 1: [Format: TIMESTAMP SESSION-ID TYPE OBJECT]

    <timestamp>: INFO: Created object /FX(200) [0975EEF8/47]
<timestamp>: INFO: Created object /FX/GBPUSD(200) [0975F0D0/48]
<timestamp>: INFO: Changing type of /FX/GBPUSD from 200 to 200 [0975F0D0/48]
<timestamp>: INFO: Changing type of /FX/GBPUSD from 200 to 222 [0975F0D0/48]
<timestamp>: INFO: </FX/GBPUSD> has changed status from 0 to 1 <All peers providing>

  4. The packet-rttpd.log file shows the raw messages routing the request to the appropriate peer DataSource application, and the data updates being received in turn. In this case the request is being routed to the application with peer id 102 i.e. Transformer. (Transformer sits in between Liberator and the Pricing Adapter.) The Pricing Adapter produces an initial (empty) message to indicate that the record exists, and subsequently the record update messages. The field names in the DataSource messages are encoded to numbers, according to how these are mapped in the fields.conf file.

    [Format: TIMESTAMP IP-ADDRESS DIRECTION TYPE PEER-ID [EXTRA]]

    <timestamp>: 127.0.0.1 > SUBJREQ 102 1 /FX/GBPUSD
<timestamp>: 127.0.0.1 < DATAUPDATE2 102 1 48 /FX/GBPUSD 222 0
<timestamp>: 127.0.0.1 < STATUS 102 /FX/GBPUSD 0x0004 0 All peers providing
<timestamp>: 127.0.0.1 < DATAUPDATE2 102 3 48 /FX/GBPUSD 222 8 -45028=/FX/GBPUSD -45029=1.67658 -45030=1.69069 -45031=GBP/USD_TIER1_S_11:08:24.549_3570 -45032=GBP/USD_TIER1_S_11:08:24.550_3573 -45033=1000000.0 -45034=1000000.0 -45035=1380190104564
<timestamp>: 127.0.0.1 < DATAUPDATE2 102 4 48 /FX/GBPUSD 222 8 -45028=/FX/GBPUSD -45029=1.82828 -45030=1.84951 -45031=GBP/USD_TIER1_S_11:08:29.551_3576 -45032=GBP/USD_TIER1_S_11:08:29.551_3579 45033=1000000.0 -45034=1000000.0 -45035=1380190109559

  5. The object-rttpd.log file shows the successful object requests made.

    [Format: TIMESTAMP SESSION-ID TYPE OBJECT]

    <timestamp>: 09IP3MJ6d-kXiF-Zra42Ie REQUEST /FX/GBPUSD (/FX/GBPUSD)

  6. Close the browser tab containing your test client to terminate the session and all subscriptions.

  7. Notice from the object-rttpd.log file, that Liberator is discarding all subscriptions made by user1.

    <timestamp>: 0hj0AjxJoIOOwP73xtuA_R DISCARD /PRIVATE/admin-0/TRADE/FX (/PRIVATE/TRADE/FX) <timestamp>: 09IP3MJ6d-kXiF-Zra42Ie DISCARD /PRIVATE/user1-0/TRADE/FX (/PRIVATE/TRADE/FX)
<timestamp>: 09IP3MJ6d-kXiF-Zra42Ie DISCARD /FX/GBPUSD (/FX/GBPUSD)

  8. The event-rttpd.log file, shows the object being deleted 1 minute later. (The subscription no longer exists and its cached image can now be deleted from memory.):

    <timestamp>: INFO: Removing session 0hj0AjxJoIOOwP73xtuA_R [09758138] code 4 <timestamp>: INFO: Removing session 09IP3MJ6d-kXiF-Zra42Ie [09757168] code 4
<timestamp>: INFO: Adding to batch-delete timer for /FX/GBPUSD(222) [0975F0D0/48]
<timestamp>: INFO: Adding to batch-delete timer for /FX(220) [0975EEF8/47]
<timestamp>: INFO: Batch discard attempting to discard /FX/GBPUSD [0975F0D0]
<timestamp>: INFO: Deleted object /FX/GBPUSD(222) [0975F0D0/48]
<timestamp>: INFO: Deleted object /FX(220) [0975EEF8/47]

  9. Note also that the packet log stops displaying updates for /FX/GBPUSD as the subscription has been terminated.

Try this yourself

  1. Investigate the Transformer packet logs to pin-point the routing of requests and update messages.

  2. If admin and user 1 are both logged in and subscribed to /FX/GBPUSD, what happens to this object on Liberator when user1’s session terminates but admin remains subscribed?

  3. What happens when the client makes a subscription to an non-existent subject e.g. /XY/GBPUSD?

  4. Use the test client to request the container with subject /CONTAINER/FX/MAJOR. In the packet log you will be able to observe how Liberator requests the container, to which it receives a container image in response. Liberator automatically uses this container image to request each record in the container.

Refiner Logs

Follow the steps below:

  1. Make a request for filtered container /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7). This container request will be processed by Refiner since it has the /FILTER prefix.

  2. Open the refiner.log file. Notice how Refiner intercepts this request and extracts the part of the request which represents the container’s subject. It then makes a request for the whole container.

    <timestamp> - Thread [pool-8-thread-1/23]: INFO: Received a request for [/FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7)].
<timestamp> - Thread [pool-8-thread-1/23]: CONFIG: /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7)- container: /CONTAINER/FX/MAJOR, mode: snapshot, filter: (BidPrice>1.7), sort: [], groupby: , username: , mapsuffix:
<timestamp> - Thread [pool-8-thread-1/23]: INFO: Creating subscription for underlying container [/CONTAINER/FX/MAJOR].
<timestamp> - Thread [pool-8-thread-1/23]: INFO: Adding requested container subscription for [/FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7)] to underlying container subscription for [/CONTAINER/FX/MAJOR].
<timestamp> - Thread [Thread-3/22]: INFO: Container updated [/CONTAINER/FX/MAJOR]. Total count [5], new subscriptions [5], discards [0], moves [0]

  3. Next, take a look at transformer.log. Transformer is creating the container object for Refiner and making the subscription to the Pricing Adapter. Refiner listens to the updates on this container.

    <timestamp>: INFO: Creating new object for </CONTAINER/FX/MAJOR> type 200 (08C7F890)
<timestamp>: INFO: Module registering listener for </CONTAINER/FX/MAJOR>
<timestamp>: INFO: Service for </CONTAINER/FX/MAJOR> is <PricingAdapterPricingSvc1> 0
<timestamp>: INFO: Requesting </CONTAINER/FX/MAJOR> from dataservices (active)
<timestamp>: INFO: Changing object type of </CONTAINER/FX/MAJOR> from 200 to 228 (08C7F890)
<timestamp>: INFO: </CONTAINER/FX/MAJOR> has changed status from 0 to 1 <All peers providing>
<timestamp>: INFO: Creating new object for </FX/GBPAUD> type 200 (08C7E010)
<timestamp>: INFO: Module registering listener for </FX/GBPAUD>
<timestamp>: INFO: Service for </FX/GBPAUD> is <PricingAdapterPricingSvc1> 0
<timestamp>: INFO: Requesting </FX/GBPAUD> from dataservices (active)
<timestamp>: INFO: Creating new object for </FX/GBPUSD> type 200 (08C80CF8)
<timestamp>: INFO: Module registering listener for </FX/GBPUSD>
...

  4. Finally analyse packet-transformer.log which shows the raw messages passing through Transformer.

    1. Liberator (peer id 101) makes a request for the filtered container.

      <timestamp>: 127.0.0.1 < SUBJREQ 101 1 /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7)

    2. This request is not propagated as is to the Pricing Adapter (peer id 1917). Instead, Transformer requests the whole container. When the Pricing Adapter responds with the container image, Transformer makes a subscription for each record in the container.

      <timestamp>: 127.0.0.1 > SUBJREQ 1917 1 /CONTAINER/FX/MAJOR
<timestamp>: 127.0.0.1 < DATAUPDATE2 1917 0 48 /CONTAINER/FX/MAJOR 228 5 1=/FX/GBPUSD 1=/FX/GBPEUR 1=/FX/GBPJPY 1=/FX/GBPAUD 1=/FX/GBPCHF
<timestamp>: 127.0.0.1 > SUBJREQ 1917 1 /FX/GBPAUD
<timestamp>: 127.0.0.1 > SUBJREQ 1917 1 /FX/GBPUSD
...
<timestamp>: 127.0.0.1 < DATAUPDATE2 1917 1 48 /FX/GBPAUD 222 0
<timestamp>: 127.0.0.1 < DATAUPDATE2 1917 2 48 /FX/GBPUSD 222 0
...
<timestamp>: 127.0.0.1 < DATAUPDATE2 1917 6 48 /FX/GBPAUD 222 8 -45028=/FX/GBPAUD -45029=1.82714 -45030=1.8482 -45031=GBP/AUD_TIER1_S_15:41:42.563_7951 -45032=GBP/AUD_TIER1_S_15:41:42.563_7954 -45033=1000000.0 -45034=1000000.0 -45035=1380206502580
...

    3. When the price updates for the records are received, Refiner determines which of these fit the criteria of the filtered request and sends a container image for the filtered request to Liberator, containing only those records' subjects for which the BidPrice is greater than 1.17.

      <timestamp>: 127.0.0.1 > DATAUPDATE2 101 3 48 /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7) 228 3 2=/FILTER/META/PLACEHOLDER Flags=0x0001,0=/FX/GBPAUD Flags=0x0001,0=/FX/GBPJPY

    4. Liberator will subsequently make a request for those records and Transformer will begin propagating data updates for those records to Liberator:

      <timestamp>: 127.0.0.1 < SUBJREQ 101 2 /FX/GBPJPY /FX/GBPAUD
<timestamp>: 127.0.0.1 > DATAUPDATE2 101 4 4144 /FX/GBPJPY 222 8 -45028=/FX/GBPJPY -45029=150.69123 -45030=150.7086 -45031=GBP/JPY_TIER1_S_15:41:42.576_7971 -45032=GBP/JPY_TIER1_S_15:41:42.576_7976 -45033=1000000.0 -45034=1000000.0 -45035=1380206502583
<timestamp>: 127.0.0.1 > DATAUPDATE2 101 6 4144 /FX/GBPAUD 222 8 -45028=/FX/GBPAUD -45029=1.82714 -45030=1.8482 -45031=GBP/AUD_TIER1_S_15:41:42.563_7951 -45032=GBP/AUD_TIER1_S_15:41:42.563_7954 -45033=1000000.0 -45034=1000000.0 -45035=1380206502580

    5. When a particular record stops meeting the criteria (in this case the bid price for GBPAUD falls below 1.17) Transformer updates the filtered container’s image on Liberator so that it no longer contains that record.

      <timestamp>: 127.0.0.1 < DATAUPDATE2 1917 11 48 /FX/GBPAUD 222 8 -45028=/FX/GBPAUD -45029=1.53685 -45030=1.57762 -45031=GBP/AUD_TIER1_S_15:41:47.562_7981 -45032=GBP/AUD_TIER1_S_15:41:47.562_7984 -45033=1000000.0 -45034=1000000.0 -45035=1380206507564
<timestamp>: 127.0.0.1 > DATAUPDATE2 101 9 48 /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7) 228 1 2=/FX/GBPAUD

    6. Likewise, when a particular record suddenly meets the criteria (e.g. GBPUSD goes above 1.17) the filtered container’s image is updated to Liberator and Liberator will subscribe to this record (if the subscription does not already exist):

      <timestamp>: 127.0.0.1 < DATAUPDATE2 1917 12 48 /FX/GBPUSD 222 8 -45028=/FX/GBPUSD -45029=1.71539 -45030=1.75007 -45031=GBP/USD_TIER1_S_15:41:47.568_7987 -45032=GBP/USD_TIER1_S_15:41:47.568_7990 -45033=1000000.0 -45034=1000000.0 -45035=1380206507570
<timestamp>: 127.0.0.1 > DATAUPDATE2 101 10 48 /FILTER/CONTAINER/FX/MAJOR?filter=(BidPrice>1.7) 228 1 Flags=0x0001,0=/FX/GBPUSD
<timestamp>: 127.0.0.1 < SUBJREQ 101 1 /FX/GBPUSD

Try this yourself

Try following the same set of steps to analyse Transformer’s and Liberator’s activities for a sorted container request.