Logging

Liberator provides comprehensive logging facilities that enable you to monitor its operation and troubleshoot problems.

Liberator is a DataSource application. For an introduction to logging in DataSource applications, with links to conceptual and reference information, see Logging in DataSource applications.

Timestamp resolution

From version 7.1 of Liberator, the resolution of log-event timestamps has been increased from millisecond to microsecond granularity. For more information, see DataSource: Timestamp resolution.

Event log

The event log, event-rttpd.log, records system events, DataSource connections, and licence usage.

For a list of event log messages related to licensing, see the Guide to user licensing (PDF).

Event log format

All event log entries use the format below.

<timestamp>: <severity>: <message>

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

Event log example

2013/08/01-13:52:17.420 +0100: CONFIG: UDP Message port not configured
2013/08/01-13:52:17.420 +0100: NOTIFY: Liberator/6.0.0 starting
2013/08/01-13:52:17.420 +0100: NOTIFY: Logging to /opt/caplin/Liberator/var
2013/08/01-13:52:17.421 +0100: NOTIFY: Licence will expire on Wed Dec 28 00:00:00 2011
2013/08/01-13:52:17.421 +0100: NOTIFY: system-max-files set to 1024
2013/08/01-13:52:17.422 +0100: INFO: Loaded auth module <openauth>
2013/08/01-13:52:17.423 +0100: INFO: Next cycle of UUPP database (/opt/caplin/Liberator/users/uupp-rttpd.db) scheduled for Wed Aug 31 23:59:59 2011
2013/08/01-13:52:17.426 +0100: INFO: Read in 101 unique users from database
2013/08/01-13:52:17.455 +0100: INFO: Created object /(220) [0x8c37578/0]
2013/08/01-13:52:17.455 +0100: NOTIFY: Field CONTRIB_USER not known, setting unique user fieldnumber to 20000
2013/08/01-13:52:17.459 +0100: INFO: 2 CPUs CONFIGURED
2013/08/01-13:52:17.459 +0100: INFO: 2 CPUs ONLINE
2013/08/01-13:52:17.493 +0100: INFO: Created object /SYSTEM(200) [0x9f41478/1]
2013/08/01-13:52:17.493 +0100: INFO: Created object /SYSTEM/NODE-0(200) [0x9f41628/2]
2013/08/01-13:52:17.493 +0100: INFO: Created object /SYSTEM/NODE-0/INFO(200) [0x9f417d0/3]
2013/08/01-13:52:17.493 +0100: INFO: Changing type of /SYSTEM/NODE-0/INFO from 200 to 201 [0x9f417d0/3]
2013/08/01-13:52:17.493 +0100: INFO: Created object /SYSTEM/INFO(200) [0x9f41a58/4]
2013/08/01-13:52:17.493 +0100: INFO: Changing type of /SYSTEM/INFO from 200 to 201 [0x9f41a58/4]
...
2013/08/01-13:52:33.642 +0100: INFO: Changing type of /SYSTEM/USERS/demouser-0 from 200 to
202 [0x9f45ce8/15]
2013/08/01-13:52:37.114 +0100: INFO: Removed object /SYSTEM/USERS/demouser-0(202)
[0x9f45ce8/15]
2013/08/01-13:52:37.114 +0100: INFO: Adding to batch-delete timer for /SYSTEM/USERS/
demouser-0(202) [0x9f45ce8/15]
2013/08/01-13:52:39.619 +0100: NOTIFY: Lost connection to peer 1 on 127.0.0.1 42371
2013/08/01-13:52:42.616 +0100: INFO: Deleted object /SYSTEM/USERS/demouser-0(202)
[0x9f45ce8/15]
2013/08/01-13:52:42.863 +0100: NOTIFY: Received signal SIGINT (2)
2013/08/01-13:52:42.864 +0100: NOTIFY: Shutting down - SIGNAL (6)

DataSource packet log

The packet log, packet-rttpd.log, records all DataSource messages sent and received by Liberator.

Packet log format

The packet log uses a binary format. To view the packet log in plain text, use the logcat command, packaged with Liberator. For more information on logcat, see View packet logs using logcat.

The logcat command converts packet log entries into the format below.

<timestamp>: <ip_address> <direction> <type> <peer_id> <EXTRA>

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

Log entry fields
Field Description

timestamp

The timestamp of the log entry.

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

ip_address

The IP address of the DataSource peer (the destination for messages sent by Liberator, and the source of messages received by Liberator).

direction

The direction of the DataSource message, in relation to Liberator:

  • '<' indicates the message was received by Liberator

  • '>' indicates the message was sent by Liberator

type

DataSource message type. See Packet log message types.

peer_id

The ID of the DataSource peer.

EXTRA

Extra information, specific to the DataSource message type. See Packet log message types.

Packet log examples

This section contains sample log entries for each message type. For a description of each message type, see Packet log message types in this section.

PEERINFO example

2011/06/26-15:04:03.201 +0100: 127.0.0.1 < PEERINFO 1 demosrcbigsun 0
2011/06/26-15:04:03.201 +0100: 127.0.0.1 > PEERINFO 0 rttpd-bigsun 0
2011/06/26-15:37:36.201 +0100: 127.0.0.1 < PEERINFO 3 testsrcmtserv1 6 Warning

DATAUPDATE2 example

2011/06/26-15:04:03.201 +0100: 127.0.0.1 < DATAUPDATE2 1 1 48 /DEMO/AAPL 8 10003=Apple 10436=21.332 10441=22.203 10006=21.767 10005=09:04 10032=2000000 10011=0.887 10005=09:04
2011/06/26-15:04:03.201 +0100: 127.0.0.1 < DATAUPDATE2 1 2 48 /DEMO/AMZN 8 10003=Amazon 10436=8.165 10441=8.499 10006=8.332 10005=09:04 10032=1700000 10011=-0.388 10005=09:04
2011/06/26-15:04:03.201 +0100: 127.0.0.1 < DATAUPDATE2 1 3 48 /DEMO/CSCO 8 10003=Cisco 10436=13.932 10441=14.501 10006=14.217 10005=09:04 10032=45700000 10011=0.347 10005=09:04

SUBJREQ example

2011/06/26-15:22:37.201 +0100: 127.0.0.1 > SUBJREQ 3 2 /I/VOD.L /I/ANL.L

SUBDSC example

2011/06/26-15:23:45.201 +0100: 127.0.0.1 > SUBJDSC 3 2 /I/VOD.L /I/ANL.L

DOWN example

2011/06/26-15:24:09.201 +0100: 127.0.0.1 < DOWN 3

NODATA example

2011/06/26-15:28:53.201 +0100: 127.0.0.1 < NODATA 3 /I/VOD.L 1
2011/06/26-15:28:53.201 +0100: 127.0.0.1 < NODATA 3 /I/ANL.L 1

STATUS example

2011/06/26-15:40:48.201 +0100: 127.0.0.1 < STATUS /I/VOD.L 0x0001 8 Data may be stale
2011/06/26-15:40:53.201 +0100: 127.0.0.1 < STATUS /I/VOD.L 0x0104 6 Data may be ok now
2011/06/26-15:40:58.201 +0100: 127.0.0.1 < STATUS /I/VOD.L 0x0004 4 Data is ok now
2011/06/26-15:41:03.201 +0100: 127.0.0.1 < STATUS /I/VOD.L 0x0000 9 Everything is fine
2011/06/26-15:41:20.201 +0100: 127.0.0.1 < STATUS /I/VOD.L 0x1101 3 Try somewhere else

Packet log message types

The table below describes the message types recorded by the packet log.

Message Type Description EXTRA parameters

PEERINFO

PEERINFO messages are sent and received when two DataSource applications negotiate a connection.

<datasource_name> <msg_id> <msg_str>

DATAUPDATE

This message type is no longer used and has been replaced by DATAUPDATE2.

-

DATAUPDATE2

DATAUPDATE2 messages are used to send object data from one DataSource peer to another.

<sequence_number> <flags> <object_name> <num_fields> <field_data>

The flags parameter is a bit field that contains meta-information that affects the way the receiving DataSource handles the object. For a full list of object bit-flags and their meanings, see Modules > Data Object Flags in the API documentation for the DataSource SDK for C (DSDK).

The field_data parameter is a space-separated list of field-value pairs. Fields are referred to by their field number in Liberator’s fields.conf file.

SUBJREQ

SUBJREQ messages are used to request object data from a DataSource peer.

<num_objects> <object_names>

The object_names parameter is a space-separated list of object names.

SUBDSC

SUBDSC messages are used to inform a DataSource peer that updates are no longer required for an object.

<num_objects> <object_names>

The object_names parameter is a space-separated list of object names.

DOWN

DOWN messages are used to record that a connection to a DataSource peer has been lost.

-

NODATA

NODATA messages are sent by a DataSource peer when it does not have a requested object, or when a subscribed object is no longer available.

<object_name> <flags>

The flags parameter can be any one of the following values:

  • 1 — NOT FOUND. The object does not exist.

  • 2 — READ DENIED. Access to this object is denied.

  • 3 — DELETE. The object has been deleted.

  • 4 — UNAVAILABLE. The object may exist but it is not available at the moment.

STATUS

STATUS messages are sent by a DataSource peer to inform another peer of the status of an object.

<object_name> <flags> <msg_id> <msg_str>

The flags parameter is a bit field that comprises the following bit flags:

  • 0x0000 — Status info

  • 0x0001 — The object is stale.

  • 0x0002 — The object is stale and should be removed from any watchlists.

  • 0x0004 — The object is not stale.

  • 0x0100 — Wait for an update. When combined with 0x0002 (stale), this flag indicates that a data update will clear the stale status. When used with 0x0100 (not stale), this indicates that the object’s non-stale status is contingent upon receiving a data update.

  • 0x1101 — Failover. The object is stale and Liberator should failover to another DataSource peer if possible.

The parameters msg_id and msg_str are user-definable.

HEARTBEAT

HEARTBEAT messages are used to detect loss of connectivity between datasource peers.

<interval> <flags>

The interval parameter is the heartbeat interval in seconds. For more information, see Enable heartbeats between DataSource applications.

The flags parameter is a placeholder and is currently unused.

Session log

The session log, session-rttpd.log, records events relating to sessions, authentication, and StreamLink heartbeats.

Session log format

All session log entries use the format below.

<timestamp>: <ip_address> <session_type> <msg_type> <username> <application_id> <session_id> <EXTRA>

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

Log entry fields
Field Description

timestamp

The timestamp of the log entry.

ip_address

The IP address of the client.

session_type

The RTTP connection type. For a full list of connection types, see Liberator RTTP configuration.

msg_type

The message type. See Session log message types.

username

The username of the user associated with the session.

application_id

The ID of the client application associated with the session.

session_id

The ID of the session.

EXTRA

Extra information, specific to each message type. See Session log message types.

Session log example

2016/04/11-13:04:53.243 +0100: 172.20.1.50 8 OPEN 0PnND5B6YJSadiLYR7S4Wt
2016/04/11-13:04:53.298 +0100: 172.20.1.50 8 LOGIN_OK user2@caplin.com SLJS:fxtrader 0PnND5B6YJSadiLYR7S4Wt LOGIN_OK
2016/04/11-13:05:01.953 +0100: 192.168.150.26 8 SYNC user1@caplin.com SLJS:fxtrader 0mEXIbUIyd2c2XTgAvTn7w clockoffset=3 latency=1
2016/04/11-13:05:04.218 +0100: 172.20.1.50 8 SYNC user2@caplin.com SLJS:fxtrader 0PnND5B6YJSadiLYR7S4Wt clockoffset=0 latency=0
2016/04/11-13:05:09.092 +0100: 172.20.1.50 8 LOST user2@caplin.com SLJS:fxtrader 0PnND5B6YJSadiLYR7S4Wt CLOSE_TYPE2
2016/04/11-13:05:11.959 +0100: 192.168.150.26 8 SYNC user1@caplin.com SLJS:fxtrader 0mEXIbUIyd2c2XTgAvTn7w clockoffset=3 latency=1
2016/04/11-13:05:16.003 +0100: 172.20.1.50 8 CLOSE user2@caplin.com SLJS:fxtrader 0GA6Z7T7h_8ACHCaUC3GeB TIMEOUT
2016/04/11-13:05:17.640 +0100: 172.20.1.50 8 OPEN 0_7-u32AUgWbcgIvqxQS62
2016/04/11-13:05:17.727 +0100: 172.20.1.50 8 LOGIN_OK user2@caplin.com SLJS:fxtrader 0_7-u32AUgWbcgIvqxQS62 LOGIN_OK
2016/04/11-13:05:21.958 +0100: 192.168.150.26 8 SYNC user1@caplin.com SLJS:fxtrader 0mEXIbUIyd2c2XTgAvTn7w clockoffset=3 latency=1
2016/04/11-13:05:28.813 +0100: 172.20.1.50 8 SYNC user2@caplin.com SLJS:fxtrader 0_7-u32AUgWbcgIvqxQS62 clockoffset=0 latency=0
2016/04/11-13:05:31.967 +0100: 192.168.150.26 8 SYNC user1@caplin.com SLJS:fxtrader 0mEXIbUIyd2c2XTgAvTn7w clockoffset=3 latency=1
2016/04/11-13:05:33.037 +0100: 172.20.1.50 8 LOST user2@caplin.com SLJS:fxtrader 0_7-u32AUgWbcgIvqxQS62 CLOSE_TYPE2
2016/04/11-13:05:39.092 +0100: 172.20.1.50 8 CLOSE user2@caplin.com SLJS:fxtrader 0PnND5B6YJSadiLYR7S4Wt TIMEOUT

Session log message types

The table below describes the message-types that are recorded by the session log.

Message Type Description EXTRA values

OPEN

New session opened.

-

CLOSE

Session closed.

Reason for closing the session.

CHUCKOUT

The server has closed the session because the server is unable to write data to the client. This can happen when the client is not consuming the data sent to it from Liberator quickly enough. The Liberator’s internal request queue fills up, causing the Liberator to terminate the session with the client. This situation could arise if the client sends a high volume of requests to the Liberator and is unable to handle the Liberator’s responses in a timely fashion (with or without network delays).

CHUCKOUT2

This code is no longer used.

CHUCKOUT3

The server has closed the session because the client has written an RTTP message line longer than direct-max-line-length. This reason code applies to direct (TCP/IP socket) connections only.

RECONNECTED

The server closed the session because the client has reconnected with a new session.

TIMEOUT

Connection with the client has been lost, and the client has not reconnected within the period set by session-reconnect-timeout.

TIMEOUT2

The client has opened a session but has not authenticated within the timeout period set by session-timeout.

CLOSE_TYPE1

Lost an RTTP direct connection.

CLOSE_TYPE2

Lost an RTTP streaming connection.

CLOSE_TYPE3

Lost an RTTP polling connection.

LOGOUT

Client logged out.

LOST

Session connection lost

Reason for loss of connection. Values as for CLOSE.

LOGIN_OK

Session logged in successfully

LOGIN_OK

RECONNECTED_OK

Session reconnected

The session ID of the previous session.

LOGIN_FAIL

Login failed.

Reason for login failure.

ACCOUNT_EXPIRED

The user account has expired.

AUTH_ERROR

Auth module error

INCORRECT_PASSWORD

Incorrect password

INVALID_IP_ADDRESS

The client’s IP address is not within the IP ranges permitted by the auth module.

SITE_LICENCE_EXCEEDED

The maximum number of concurrent users has been exceeded, or the maximum number of unique users over the licensing monitoring period has been exceeded.

USER_LICENCE_EXCEEDED

The maximum number of concurrent sessions for the user has been exceeded.

USER_UNKNOWN

Invalid username

LOGOUT_OK

Session logged out

LOGOUT_OK

SYNC

Streamlink heartbeat

Space-separated set of field-value pairs used in latency measurement.

clockoffset=<offset> latency=<latency>

Object log

The object log, object-rttpd.log, records the following object operations: requests, maps, and discards.

Object log format

All object log entries use the format below.

<timestamp>: <session_id> <operation_type> <object_post_map> (<object_pre_map>)

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

Log entry fields
Field Description

timestamp

The timestamp of the log entry.

session_id

The client’s session ID.

operation_type

The operation type. Valid values: 'MAP', 'REQUEST' and 'DISCARD'.

object_post_map

Name of the object after object mapping has been applied. This is the name of the object hosted by Liberator.

object_pre_map

Name of the object before object mapping has been applied. This is the name of the object as requested by the client.

Object log example

2009/09/07-11:57:33.810 +0100: 9bjLYd MAP /HBT/snpsrc-frac (/snpsrc-frac)
2011/06/25-08:27:06.201 +0100: 0000Fw REQUEST /HBT/snpsrc-frac (/snpsrc-frac)
2009/06/25-08:27:07.201 +0100: 0000Fw MAP /HBT/snpsrc-deci (/snpsrc-deci)
2009/06/25-08:27:07.201 +0100: 0000Fw REQUEST /HBT/snpsrc-deci (/snpsrc-deci)
2009/06/25-08:37:10.201 +0100: 0000Fw DISCARD /HBT/snpsrc-frac (/snpsrc-frac)

RTTP request log

The RTTP request log, request-rttpd.log, records object requests received by Liberator.

RTTP request log format

All RTTP request log entries use the format below.

<timestamp>: <ip_address> <username> <session_id> "<message>"

Prior to Liberator 7.1, the timestamp has a resolution of one millisecond. From Liberator 7.1, the timestamp has a resolution of one microsecond.

Log entry fields
Field Description

timestamp

The timestamp of the log entry.

ip_address

The IP address of the client.

username

The username associated with the session.

session_id

The ID of the session.

message

The raw RTTP message.

RTTP request log example

2011/06/26-15:04:42.201 +0100: 192.168.201.16 - 2ADgSL "2ADgSL LOGIN 000000 CLIENT/CLEAR RTTP/2.0 demouser demopass"
2011/06/26-15:04:46.201 +0100: 192.168.201.16 demouser 2ADgSL "2ADgSL LOGOUT"
2011/06/25-04:11:27.201 +0100: 192.168.201.210 maggie 0004p_ "0004p_ REQUEST /EQUITIES/MSFT"
2011/06/25-04:11:27.201 +0100: 192.168.201.210 maggie 0004p_ "0004p_ REQUEST /FX/GBP"
2011/06/25-04:11:28.201 +0100: 192.168.201.210 maggie 0004p_ "0004p_ REQUEST /IPE/IPE/HB"
2011/06/25-04:14:17.201 +0100: 192.168.201.104 - 0006IW "0006IW NOOP"
2011/06/25-04:14:17.201 +0100: 192.168.201.104 - 0006IW "0006IW LOGIN 0003UCLIENT/CLEAR RTTP/0.2 bobby11 mypassw11"
2011/06/25-04:21:08.201 +0100: 192.168.201.121 - 0004dG "0004dG NOOP"
2011/06/25-04:21:08.201 +0100: 192.168.201.121 - 0004dG "0004dG LOGIN 00077o CLIENT/CLEAR RTTP/0.2 bobby11 mypassw11"
2011/06/25-04:21:32.201 +0100: 192.168.201.210 maggie 0004p_ "0004p_ LOGOUT "
2011/06/25-04:22:34.201 +0100: 192.168.201.210 - 1002i0 "1002i0 LOGIN 000000 CLIENT/CLEAR RTTP/0.2 maggie password"
2011/06/25-04:22:34.201 +0100: 192.168.201.210 maggie 1002i0 "1002i0 REQUEST /EQUITIES/MSFT"
2011/06/25-04:22:34.201 +0100: 192.168.201.210 maggie 1002i0 "1002i0 REQUEST /FX/GBP"
2011/06/25-04:22:34.201 +0100: 192.168.201.210 maggie 1002i0 "1002i0 REQUEST /IPE/IPE/HB"
2011/06/25-04:32:39.201 +0100: 192.168.201.210 maggie 1002i0 "1002i0 LOGOUT "

RTTP traffic logs

The RTTP traffic logs record raw RTTP messages exchanged between a Liberator and its clients. RTTP traffic logging is intended for troubleshooting only; the log files increase in size too quickly for use in production deployments.

RTTP logging is disabled by default. For information on enabling and interpreting the RTTP traffic log, see Server-side RTTP logging (PDF).

HTTP access log

The HTTP access log, http-access-rttpd.log, records all HTTP requests received by the Liberator.

HTTP access log format

The HTTP access log is in standard Common Log Format.

HTTP access log example

192.168.201.16 - - [26/Jul/2011:15:04:34 +0100] "GET /demos/rtml/rtml.html HTTP/1.1" 200 2192
192.168.201.16 - - [26/Jul/2011:15:04:34 +0100] "GET /demos/rtml/common.css HTTP/1.1" 200 522
192.168.201.16 - - [26/Jul/2011:15:04:34 +0100] "GET /rtml/ HTTP/1.1" 200 9570
192.168.201.16 - - [26/Jul/2011:15:04:35 +0100] "GET /rtml/lib/formatting.js HTTP/1.1" 200 3769
192.168.201.16 - - [26/Jul/2011:15:04:35 +0100] "GET /rtml/lib/stale.js HTTP/1.1" 200 1167
192.168.201.16 - - [26/Jul/2011:15:04:35 +0100] "GET /rtml/w3clibrary.js HTTP/1.1"200 3122

HTTP error log

The HTTP error log, http-error-rttpd.log, records all HTTP errors.

HTTP error log format

All HTTP error log entries use the format below.

[<timestamp>] [<severity>] [client <ip_address>] <message>

HTTP error log example

[26/Jun/2011:11:47:09.123 +0000] [error] [client 127.0.0.1] File does not exist: /opt/Liberator/htdocs/notfound

See also: