...
The logging hierarchy identified is not suitable to be directly used by Log4j as there is multiple routes and loops in the graph.
To better address this and to allow us to more eaily move between logging implementations an abstraction is recommended. This approach will allow the simplification of the logic around determining if logging should be performed in the main code base. For example a Binding logging statement can be controlled via Exchange and Queue, each of which may be limited to s specific instanceAbstracting the logging is recommended as this will allow us to simply provide Qpid specific optimisations such as providing the log prefix.
This design will cover the following areas:
Contents
Table of Contents | ||||
---|---|---|---|---|
|
Logging Control
Initialy the use of a properties file will be used to enable/disable various logging options. The property value will be one of a set list. This will help avoid the ambigious parsing of Java Properties files.
No Format | ||
---|---|---|
| ||
# Comment Line
<logger> = <value [OFF|TRACE|DEBUG|INFO|WARN|ERROR|FATAL|ALL]>
|
The values for the <logger> are based on navigation through the hierarchy.
Hierarchy Refinement
...
qpid ─┬─ broker
│
│
│ ┌── [<username>] ───┐
│ ├─ [<ip/hostname>] ─┤
├─ connection ─┴───── [<id>] ──────┴─ channel ── [<id>] ──────┬── subscription ── [<id>]
│ │
└─ virtualHost ── <name> ─┐ ┌─ binding │
│ │ │
├─ exchange ── <name> ─┤ │
│ │ │
├─ queue ── <name> ────┴────────────┘
│
├─ plugin ── <name>
│
└─ messagestore
|
Additional Documentation
Logging Configuration
At this stage configuration will be limited to the addition to the main config.xml file of the following option:
Code Block | ||||
---|---|---|---|---|
| ||||
<broker>
...
<status-updates>ON</status-updates>
...
</broker>
|
This status-update on setting will be the default value if the section is not included in the configuration file. The setting will be global for all virtualhosts and will be exposed via the management console as logger 'qpid.status' to allow dynamic setting.
The ability to configure more fine grained logging will be investigated here, but will not be implemented in the initial phase.
Status Updates
In the first phase updates only status updates will be provided. Status updates should take the form of general operational logging level, no logging on message delivery path way and No performance impact. The recommendation will be to have these enabled for production use.
e.g. Creation/Destruction events
The status updates can also be used in a second phase to provide additional logging to assist development.
The additional logging can be performed on the message delivery path way. This may have performance impact and so would not be recommended for long term production use.
e.g. Message Enqueue/Dequeue
Logging Abstraction
The abstraction layer allows us to fully decouple the logging mechanism from any operational logging that the broker may wish to perform. The following code highlights show how we would abstract the logging operations.
The approach to logging is that a LogActor will be recoreded as a ThreadLocal and will be used to perform logging the log messages as highlighted on Logging Format Design. The LogActor will take two parameters, the LogSubject and the LogMessage. When a Status event occurs that should be logged the LogActor can be retrieved from the thread thus avoiding passing the LogActor through as a parameter to all locations were it must be logged. The initial LogActors will be AMQPActor and ManagementActor. Later phases would introduce HouseKeepingActor. These LogActors are responsible for checking that the logging should be performed for both themselves and the LogSubject. The LogActor then provids their log formatted name as per the format design along with the message to the RootMessageLogger. Initially the configuration will be a simple on/off, however, in a future phase the details can be used to identify if logging should proceed for that LogActor and LogSubject combination. At this stage selective configurations is not part of this design.
The use of the LogActor allows for situations such as Binding to have a Connection associated with the Binding. This will allow a Binding create event to be logged like this:
No Format |
---|
2009-06-29 13:35:10,1234 +0100 MESSAGE [con:1(guest@127.0.0.1/)/ch:2] [ex(amq.direct)/qu(testQueue)/bd(routingKey)] BND-1001 : Binding Created
|
rather having no details about how the creation occurred:
No Format |
---|
2009-06-29 13:35:10,1234 +0100 MESSAGE [ vh(/)/ex(amq.direct)/qu(testQueue)/bd(routingKey) ] BDN-1001 : Create
|
Interfaces
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
/**
* LogActor the entity that is stored as in a ThreadLocal and used to perform logging.
*
* The actor is responsible for formatting its display name for the log entry.
*
* The actor performs the requested logging.
*/
public interface LogActor
{
/**
* Logs the specified LogMessage about the LogSubject
*
* Currently logging has a global setting however this will later be revised and
* as such the LogActor will need to take into consideration any new configuration
* as a means of enabling the logging of LogActors and LogSubjects.
*
* @param actor The actor that is requesting the logging
* @param message The message to log
*/
public void message(LogSubject subject, LogMessage message);
}
|
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
/**
* Each LogSubject that wishes to be logged will implement this to provide their
* own display representation.
*
* The display representation is retrieved through the toString() method.
*/
public interface LogSubject
{
/**
* Logs the message as provided by String.valueOf(message).
*
* @returns String the display representation of this LogSubject
*/
public String toString();
}
|
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
/**
* The RootMessageLogger is used by the LogActors to query if
* logging is enabled for the requested message and to provide the actual
* message that should be logged.
*/
public interface RootMessageLogger
{
/**
* Determine if the LogSubject and the LogActor should be
* generating log messages.
*
* @param logSubject The subject of this log request
* @param logActor The actor requesting the logging
* @return boolean true if the message should be logged.
*/
boolean isMessageEnabled(LogActor actor, LogSubject subject);
/**
* Log the raw message to the configured logger.
*
* @param message The message to log
* @param throwable Optional Throwable that should provide stact trace
*/
void rawMessage(String message, Throwable throwable);
}
|
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
/**
* A RawMessage Logger takes the given String and any Throwable and writes the
* data to its resource.
*/
public interface RawMessageLogger
{
/**
* Log the message and formatted stack trace for any Throwable.
*
* @param message String to log.
* @param throwable Throwable for which to provide stack trace.
*/
public void rawMessage(String message, Throwable throwable);
}
|
This hierachy has a number of paths which make it more difficult to process.
- Connection can be optionally followed with up to one of the following: username,ip/host, id
- Subscription can be reached through Connection and Virtualhost
- Exchange and Queue can be added in either order
- Binding can be routed through Queue and Exchange, or both in either order.
It is these difficulties that make it best to provide an abstraction layer so that a simple interface can be used at the site of the logging. These difficulties can be distilled to:
- Procsessing values for all values of '<name>'
- Overlapping configuration resolution
- Presentation of entities with multiple paths
Procsessing values for all values of '<name>'
To ensure that the logger path is processable the '<name>' must be present to make it easier to understand when we have an identifier or a <name> value. i.e. Is this logging all events for exchanges on Virtualhost called 'queue' or logging all exchange events that occur in relatation to queues.
No Format |
---|
qpid.virtualhost.queue.exchange = INFO
|
By introducing the use of the '*' wild card we can make these two situations easier to read:
No Format |
---|
qpid.virtualhost.queue.exchange = INFO
qpid.virtualhost.*.queue.exchange = INFO
|
The '*' can then be used at the end of the logger to ensure all logging from this point in the hierarchy will be logged, rather than just events to the specified entity.
Overlapping configuration resolution
The loops in the graph will be handled by the logger configurator so that only one log entry is created for each event, even if there are multiple matching entries in the configuration. For example, the follow two entries are equivalent and will both enable all loging for bindings. If the user wishes to log all binding operations then only one entry is necessary but the presence of both should not cause duplicate messages.
No Format | ||
---|---|---|
| ||
qpid.virtualhost.*.exchange.*.binding = INFO
qpid.virtualhost.*.queue.*.binding = INFO
|
The overlapping of configuration such as logging all details of connection from user guest and from ip 127.0.0.1 will not result in a duplicated logging if guest connects from 127.0.0.1.
No Format | ||
---|---|---|
| ||
qpid.connection.guest.* = INFO
qpid.connection.<127.0.0.1>.* = INFO
|
Presentation of entities with multiple paths
Each entitiy will have a prescribed log format which will be designed to take into consideration its place in the hierarchy, see Logging Format Design for further details.
Log Configuration processing
The configuration will be processed top-to-bottom. This allows for defaults to be set and specific cases to have further logging enabled. The example below enables INFO logging for all events and specifically adds DEBUG logging for all activity related to the user 'guest'.
No Format | ||
---|---|---|
| ||
qpid.* = INFO
qpid.connection.guest,* = DEBUG
|
Logging Abstraction
The abstraction layer allows us to fully decouple the logging mechanism from any operational logging that the broker may wish to perform.
Code Block | |
---|---|
java | java |
title | OperationalLogging Interface |
public boolean isInfoEnabledForPlugin(Plugin p, Object o);
public void pluginInfo(Plugin p, Object o);
public void pluginInfo(Plugin p, Object o, Throwable throwable);
public boolean isInfoEnabled(Object o);
public void info(Object o);
public void info(Object o, Throwable throwable);
...
// Repeated for each level TRACE|DEBUG|INFO|WARN|ERROR|FATAL
|
Logging Usage
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
pubic class SubscriptionConnection ... if (_statusLogger.isInfoEnabled(this)) { _statusLogger.info(this, "Subscription Event occured."); }LogActor amqpActor = // retrieved from ThreadLocal. //_channelSubject is an instance LogSubject that knows how to represent this Connection amqpActor.logMessage(_connectionSubject, LogMessages.CHANNEL_CREATE(this)); ... |
Would result in the following based on the Logging Format Design.
No Format |
---|
2009-06-29 13:35:10,1234 +0100 MESSAGE [ con:1(guest, 127guest@127.0.0.1, /)/] [ch:2/sub:1:qu(myqueue) ] Subscription Event occcured.] ChM-1001 : Channel Created |
Code Block | ||||||
---|---|---|---|---|---|---|
| ||||||
pubic class Channel ... plugin = getACLPlugin(); ... if amqpActor.logMessage(_statusLogger.isInfoEnabledForPlugin(plugin, this)) { _statusLogger.pluginInfo(plugin, this, "Plugin Event occured for this."); }subsriptionSubject, LogMessages.SUBSCRIPTION_CREATE(this)); ... |
Would result in the following:
No Format |
---|
2009-06-29 13:35:10,1234 +0100 MESSAGE [ con:1(guest, 127guest@127.0.0.1, /)/ch:2/pl(ACL, Consume, qu(myQueue)) ] Plugin Event occured for this. |
Initial Log Messages
] [sub:1:qu(myqueue)] Sub-1001 : Subscription Created
|
Initial Status Messages
Broker
Startup
Configuration details
Ready
Shutdown
ManagementConsole
Startup
Configuration details
Ready
Close
VirtualHost
Create
Configuration details
Close
MessageStore
Startup
Recover Status
Start
Progress
End
Close
Connection
Open
Close
Channel
Create
Flow Status
Destroy
Queue
Create
Destroy
Exchange
Create
Destroy
Binding
Create
Destroy
Subscription
Create
DestroyTBC