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.

Contents:

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: