Rhapsody uses the log4j framework for its logging capabilities, which provides significant control to the user at runtime. The logging framework is configured in the log4j.properties file, found in the <Rhapsody>\rhapsody folder (and through the Management Console for communication points and routes). When Rhapsody has been started, log4j monitors this configuration file, and reloads changes while Rhapsody is running (normally this takes approximately one minute). This means that the logging levels can be modified without any downtime.

Log4j primarily relies on two concepts for logging: loggers, and appenders.

Making inconsistent changes to the log4j.properties file while the engine is running could have unintended side effects such as the inability to log into Rhapsody IDE or the Management Console. For example, if you are changing the type of appender, ensure that only the settings relevant to the new appender type are specified before saving the log4j.properties file.

Loggers

Log4j allows for multiple loggers to be created, operating in a hierarchical manner. The root logger, called 'Rhapsody', contains all logging information produced by Rhapsody, whereas all other loggers are lower in the hierarchy and so contain a subset of that information.

Rhapsody defines a number of loggers internally, within the hierarchy provided by log4j. This hierarchy is described below:

  • Rhapsody - this is the root logger, and all log messages are always sent to this log. Consequently, the threshold of this logger is normally set higher than the other loggers, as otherwise too much logging information may be reported.
  • Symphonia - the Symphonia logger contains all logging information produced by the parsing engine, which is used for processing EDI messages, and mapping messages. It contains all logging information that are in one of its sub-categories.
    • load - logging information in the parser relating to loading message definitions.
    • parse - logging information in the parser relating to parsing messages.
    • validate - logging information in the parser relating to validating messages.
  • Database - this logger contains debug information about all SQL commands executed by Rhapsody, both for its internal persistence mechanism, and for all database communication points and filters. Consequently, this logs a lot of information when enabled, and consequently must be enabled specifically by adding the following line to the rhapsody.properties file; RhapsodyDriverManager.DebugMode=true.
  • ArchiveCleanupScheduler - this logger contains logging information about the archive cleanup mechanism in Rhapsody, and when it is being run.
  • <Communication Point/Filter ID> - each communication point and filter has its own category at this level, with the category name the same as the component ID. These loggers will contain information specific to that communication point or filter.

The full category name is determined by joining together the various levels of the hierarchy. For example, the full category name for loading EDI message definitions is Rhapsody.Symphonia.load.

Log4j Appenders

Log4j appenders are what actually perform the logging of tracing information to disk or via another method. Appenders are attached to loggers, and define how the logging information is logged and the threshold for reporting logging information. Any number of appenders at different thresholds may be attached to a single logger. Log4j defines a number of default appenders that may be used including the following:

  • RollingFileAppender - a log file on disk that is automatically rolled over when it reaches a set maximum file size. Meaning that the oldest information is perpetually overwritten by new information on a cyclic basis.
  • NTEventLogAppender - an appender that can write to the Windows® NT event log.

Logging Levels

Log4j employs a system of logging levels in order to determine what log statements are written to the log files. The standard log levels are as follows from lowest to highest (where lowest is the most detailed level of tracing):

  • OFF - no logging information is reported.
  • FATAL - logs very severe error events that generally cause the application to stop.
  • ERROR - logs error events that generally still allow the application to continue running.
  • WARN - logs potentially harmful situations.
  • INFO - logs informational messages that highlight the progress of the application at a coarse-grained level.
  • DEBUG - all debugging information is reported. Non-error tracing information that is logged on a per message basis should always be logged at this level. It contains fine-grained informational events that are useful for debugging.
  • TRACE - all tracing information is reported. It contains additional fine-grained informational events that are useful for debugging.
  • ALL - all logging information is reported.

When setting a log level in the log4j.properties file or in the Management Console, any log entries at the same or higher level than the log level set on a logger are written to the log file set in any stipulated log appenders. For example, if the log level is set to Info, then all Info, Warn, Error and Fatal log messages are written to the log file.

The logging system relies on two key behaviors for fine-grained control of logging on a per component and per level basis:

  • Overrides - the logging system employs a hierarchical structure of components whereby different components can have different logger objects associated. Logging levels in sub-components override any logging level set in parent components.
  • Appender Additivity - logger objects themselves are additive in that log messages go to all relevant appenders for a specific component. Therefore, if a logger object is created for a child object, messages go to the appenders defined for the new logger object as well as to any parent loggers defined (for example, the root logger).

Log4j Layout Format

All the default appenders for Rhapsody use the PatternLayout log4j layout. The conversion pattern for these layouts can be configured reasonably extensively.

The conversion pattern is closely related to the conversion pattern of the print function in C. A conversion pattern is composed of literal text and format control expressions called conversion specifiers.

Each conversion specifier starts with a percent sign (%) and is followed by optional format modifiers and a conversion character. The conversion character specifies the type of data; for example, category, priority, date, thread name. The format modifiers control such things as field width, padding, left and right justification. The following is a simple example.

Let the conversion pattern be "%-5p [%t]: %m%n" and assume that the log4j environment was set to use a PatternLayout.

  • Category root = Category.getRoot();
  • root.debug("Message 1");
  • root.warn("Message 2");
  • would yield the output...
  • DEBUG [main]: Message 1
  • WARN [main]: Message 2

There is no explicit separator between text and conversion specifiers. The pattern parser knows when it has reached the end of a conversion specifier when it reads a conversion character. In the example above the conversion specifier %-5p means the priority of the logging event should be left justified to a width of five characters.

The recognized conversion characters are described in the following table:

Conversion Character

Effect

c

Used to output the category of the logging event. The category conversion specifier can be optionally followed by precision specifier that is a decimal constant in brackets.

If a precision specifier is given, then only the corresponding number of right most components of the category name will be printed. By default, the category name is printed in full. For example, for the category name a.b.c, the pattern %c{2} will output b.c.

C

Used to output the fully qualified class name of the caller issuing the logging request. This conversion specifier can be optionally followed by precision specifier, which is a decimal constant in brackets.

If a precision specifier is given, then only the corresponding number of right most components of the class name will be printed. By default, the class name is output in fully qualified form.

d

Used to output the date of the logging event. The date conversion specifier may be followed by a date format specifier enclosed between braces.

For example, %d{HH:mm:ss,SSS} or %d{dd MMM yyyy HH:mm: ss,SSS}. If no date format specifier is given then ISO8601 format is assumed.

F

Used to output the file name where the logging request was issued.

Generating caller location information is extremely slow. Its use should be avoided unless execution speed is not an issue.

l

Used to output location information of the caller which generated the logging event.

L

Used to output the line number from where the logging request was issued.

m

Used to output the application supplied message associated with the logging event.

M

Used to output the method name where the logging request was issued.

n

Outputs the platform dependent line separator character or characters.

This conversion character offers practically the same performance as using non-portable line separator strings such as \n, or \r\n. Thus, it is the preferred way of specifying a line separator.

p

Used to output the priority of the logging event.

r

Used to output the number of milliseconds elapsed since the start of the application until the creation of the logging event.

t

Used to output the name of the thread that generated the logging event.

x

Used to output the NDC (nested diagnostic context) associated with the thread that generated the logging event.

X

Used to output the MDC (mapped diagnostic context) associated with the thread that generated the logging event. The X conversion character must be followed by the key for the map placed between braces, as in %X{clientNumber} where clientNumber is the key. The value in the MDC corresponding to the key will be output.

%

The sequence %% outputs a single percent sign.

Refer to Class PatternLayout for details.

Logging to the Windows Event Log

The NTEventLogAppender.dll file is included in the \Rhapsody\bin directory, so that Log4j can log events to the Windows® Event Log.

To enable logging to the Windows® NT event log:

  1. Uncomment the following lines in the log4j.properties file:

    # Windows NT Event Log Appender
log4j.appender.NT=org.apache.log4j.nt.NTEventLogAppender
log4j.appender.NT.layout=org.apache.log4j.PatternLayout
log4j.appender.NT.layout.ConversionPattern=%d{DATE} %-5p [%t] (%c) %m%n
log4j.appender.NT.Threshold=ERROR
log4j.appender.NT.Source=Rhapsody

  2. Add NT to the log4j.rootLogger=INFO,NormalAppender line at the top of the log4j.properties file:

    # Default Logging Setting
log4j.rootLogger=INFO,NormalAppender,NT

Viewing Raw SOAP Requests and Responses

The transformation of Rhapsody messages to and from SOAP messages occurs within the communication points, and is therefore not visible in the message path. However, you can turn on logging for the raw requests, responses and faults.

This produces a large number of log messages, and is therefore disabled by default.

There are four logging points for each web service. This allows logging both before and after any signing/encryption transformations are carried out. Modifying the log4j.properties file enables all these logging points:

  • Incoming message before security (transport.request/transport.response).
  • Incoming message after security (dispatch.request/dispatch.response).
  • Outgoing message before security (dispatch.response/dispatch.request).
  • Outgoing message after security (transport.response/transport.request).

The request/response names are reversed for the web service client and web service host.

To enable logging for a web service hosted by Rhapsody, add the following line to the log4j.properties file:

log4j.logger.WebService.<id>=TRACE

To enable logging for a web service client, add the following line to the log4j.properties file:

log4j.logger.CommunicationPoint.<id>.webservice=TRACE

<id> is the integer identifier of the web service. View the service in the Management Console to locate the <id>.

Logging User and Group Permission Changes

When a user is created, the groups it is added to are audit logged at the INFO level: 

17 May 2018 13:25:12,678 [INFO ] {Session-/127.0.0.1:50545} (User.Administrator) Added user 'bob' 
17 May 2018 13:25:12,678 [INFO ] {Session-/127.0.0.1:50545} (User.Administrator) Added users 'bob' to the 'Administrator' group 
17 May 2018 13:25:12,678 [INFO ] {Session-/127.0.0.1:50545} (User.Administrator) Added users 'bob' to the 'Developer' group 

When the groups a user belongs to groups are modified, the changes are audit logged:

17 May 2018 14:31:00,933 [INFO ] {Session-/127.0.0.1:50545} (User.Administrator) Removed users 'bob' from the 'Developer' group 
17 May 2018 14:32:17,433 [INFO ] {Session-/127.0.0.1:50545} (User.Administrator) Added users 'bob' to the 'Dashboard' group

When a group is created or modified, a full list of access rights for the group is audit logged:

10 May 2018 13:46:41,551 | 174477      [INFO] {Session-/127.0.0.1:52821} (User.Administrator) Group 'Developer' global and default locker rights:
	Login to IDE,
	Make changes with IDE,
	Login to Web Management Console,
Group 'Developer', locker 'New Locker' access rights:
	View Locker,
	Run Intelligent Mapper tests,
	View message in an emergency
Group 'Developer', locker 'Locker' access rights:
	View Locker,
	Edit Locker,
	Search Message Queues,
	Search Error and Hold Queues,
	View Support Notes,