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>
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 message types

There are nine DataSource message types.

PEERINFO

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

EXTRA fields
<datasource_name> <msg_id> <msg_str>
Example PEERINFO messages
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

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.

EXTRA fields
<sequence_number> <flags> <object_name> <data_object_type> <num_fields> <field_data>

flags 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).

data_object_type is an integer constant indicating the DataSource data type. For the list of constants, see Data object types in the DataSource SDK for C (DSDK) documentation.

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

Example DATAUPDATE2 messages
2011/06/26-15:04:03.201 +0100: 127.0.0.1 < DATAUPDATE2 1 1 48 /DEMO/AAPL 222 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 222 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 222 8 10003=Cisco 10436=13.932 10441=14.501 10006=14.217 10005=09:04 10032=45700000 10011=0.347 10005=09:04

SUBJREQ

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

EXTRA fields
<num_objects> <object_names>
Example SUBJREQ message
2011/06/26-15:22:37.201 +0100: 127.0.0.1 > SUBJREQ 3 2 /I/VOD.L /I/ANL.L

SUBDSC

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

EXTRA fields
<num_objects> <object_names>
Example SUBDSC message
2011/06/26-15:23:45.201 +0100: 127.0.0.1 > SUBJDSC 3 2 /I/VOD.L /I/ANL.L

DOWN

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

DOWN messages do not have EXTRA fields.

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

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.

EXTRA fields
<object_name> <flags>

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

Flag Value Description

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.
Example NODATA messages
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

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

EXTRA fields
<object_name> <flags> <msg_id> <msg_str>

flags 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 fields msg_id and msg_str are user-definable.

Example STATUS messages
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

HEARTBEAT

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

EXTRA fields
<interval> <flags>

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

The flags field 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.

EJECTED

The server has closed the connection in order to remain within configured or licensed restrictions on usage. When auth-eject-users is set to true, Liberator enforces usage restrictions by giving new connections precedence over existing connections. Rather than reject a new connection that would cause Liberator to exceed a usage restriction, Liberator accepts the new connection and closes its oldest connection. For more information on usage restrictions, see max-user-limit and Licence management.

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.

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.

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: