Page History

...

A series of test must be written that cover all the log messages that the broker will generate. The approach to valiate validate any performance changes should then be to run the test multiple times to generate an average performance. The impact of the logging additions must be negligablenegligible. The performance test suite has shown that that there can be up to 5% variance between test runs so if this testing is to be performed as an automated system test we must be careful to ensure that we do not end up with test failures due to an unusaly unusually variance. Testing should be performed to establish a baseline from which we can determine what amount of varience variance occurs between the two test runs. This varience variance can then be used to determine the failure criteria. However, it should be noted that such a comparison technique will only ensure that the impact of the logging does not shift between each run. The test will not address any potential drift in performance of the broker as a whole, only the difference between logging on and logging off.

The test should run with interleaved test setups, i.e. Logging On then Loggging off. This will help minimise any external factors that could impact the timing. The time spent logging however, will still represent a very small percentage of time for a test case and as such the test will be more susceptible to other external factors during the test run.

Operation Testing

There are two componente components to testing the functionality of the new logging.

...

Unit Testing

Unit testing must be compelted completed on each module and code coverage should cover at least 80% (aiming towrds towards 100%) of the codebasecode base. The unit testing however, will only verify that the module performs as expected with the use of a test output logger that the module performs as expected.

System Testing

System testing will need to be performed to validate that the correct log messages appear in the right order when run as a full system. By using the test output logger used for the Unit testing it will be possible to validate an InVM broker correctly logs at the appropriate time. To complete system testing the log4j output from an external broker test run must be examined to ensure it contains the expected output. The alerting tests already perform this sort of external log validation so this should be easy to repllicatereplicate.

Additionally, we will want to add tests to understand how the system behaves under certain failure conditions. This will not be required as part of this initial work. However, when we remove log4j we need to understand what the differences will with any new logging framework in failure situations, i.e. disk Fullfull, disk loss(crash, NFS delay).

Test Plan

The Functional Specificiation lists the various status log messages that the broker will be configured to produce. What this section details is how testing will be carried out for each of these log statements.

Broker

The Broker messages can be split in to two categories. Startup and shutdown messages. The testing here focuses on the Broker messages and ignore the fact that during a system testing of the broker other log messagse will also be printed.

Startup

As all the startup messages are printed on startup then they cannot be printed individually. So we by monitoring the logging output on startup we can verify that messages BKR -1001,1002,1004,1006,1007 are logged. It is expected that the output would be very similar to this:

The difference with a disk loss (crash, NFS delay) is the write IO will not necessarily respond immediately while a disk full notification will usually respond immediately.

Performance Test Plan

The performance of the broker can be measured by the JMS Client by ensuring that all the updated modules are executed in the test run. The time it takes to startup create a new JMS Session and subscribe and the cleanly shut everything down will ensure all of the new log messages have the option of logging. Now the overhead in broker startup and shutdown will have a large effect on the test run however this should mean it will be easier to compare startup times as they should be very similar.

Operational Test Plan

The Functional Specificiation lists the various status log messages that the broker will be configured to produce. What this section details is how testing will be carried out for each of these log statements.

Broker

The Broker messages can be split in to two categories. Startup and shutdown messages. The testing here focuses on the Broker messages and ignore the fact that during a system testing of the broker other log messages will also be printed.

Startup

As all the startup messages are printed on startup then they cannot be printed individually. So by monitoring the logging output on startup we can verify that messages BKR-1001,1002,1004,1006,1007 are logged. It is expected that the output would be very similar to this:

2009-07-09 15:50:20 +0100 MESSAGE BRK-1006 : Using configuration : build/etc/config.xml
2009-07-09 15:50:20 +0100 MESSAGE BRK-1007 : Using logging configuration : build/etc/log4j.xml
2009-07-09 15:50:20 +0100 MESSAGE BRK-1001 : Startup : Version: 0.6 Build: <svn revision>
2009-07-

2009-07-09 15:50:20 +0100 MESSAGE BRK-1006 : Using configuration : build/etc/config.xml1002 : Starting : Listening on TCP port 5672
2009-07-09 15:50:20 +0100 MESSAGE BRK-1004 : Ready

Additionally testing should be performed with SSL enabled to verfify that the additional BRK-1002 message is logged.

2009-07-09 15:50:20 +0100 MESSAGE BRK-10071002 : UsingStarting logging: configurationListening :on TCP/SSL port 8672.

Shutdown

On shutdown the broker will log a BRK-1003 for each interface that has been started. So if we have started both the TCP and the TCP/SSL listeners then we would expect both to be printed out before the Stopped message.

build/etc/log4j.xml
2009-07-09 15:50:20 +0100 MESSAGE BRK-1001 : Startup : Version: 0.6 Build: <svn revision>
2009-07-09 15:50:20 +0100 MESSAGE BRK-10021003 : Shutting Startingdown : Listening on TCP port 5672
2009-07-09 15:50:20 +0100 MESSAGE BRK-10041003 : Shutting down : Ready

Additionally testing should be performed with SSL enabled to verfify that the additional BRK-1002 message is logged.

TCP/SSL port 8672
2009-07-09 15:50:20 +0100 MESSAGE BRK-1002 : Starting : Listening on TCP/SSL port 8672.

Shutdown

:20 +0100 MESSAGE BRK-1005 : Stopped

ManagementConsole

The management console also has a startup and shutdown phase like the broker.

Startup

The Management console uses two ports so both of these will be logged at startup. Two test runs must be performed to validate that the 'SSL Keystore' output is only present when correctly enabledOn shutdown the broker will log a BRK-1003 for each interface that has been started. So if we have started both the TCP and the TCP/SSL listeners then we would expect both to be printed out before the Stopped message.

2009-07-09 15:50:20 +0100 MESSAGE BRKMNG-10031001 : Shuting down : TCP port 5672Startup
2009-07-09 15:50:20 +0100 MESSAGE BRK-1003 MNG-1002 : Starting : ShutingRMI downRegistgry : Listening TCP/SSLon port 86728999
2009-07-09 15:50:20 +0100 MESSAGE BRK-1005 : Stopped

ManagementConsole

The management console also has a startup and shutdown phase like the broker.

Startup

The Management console uses two ports so both of these will be logged at startup. Two test runs must be performed to validate that the 'SSL Keystore' output is only present when correctly enabled.

MNG-1002 : Starting : RMI ConnectorServer : Listening on port 9099
2009-07-09 15:50:20 +0100 MESSAGE MNG-1001 : Startup1006 : Using SSL Keystore : test_resources/ssl/keystore.jks
2009-07-09 15:50:20 +0100 MESSAGE MNG-1002 : Starting1004 : Ready

Shutdown

During shutdown the two listeners created during startup will shutdown. The use of SSL will not provide any additional shutdown mesasage to verify.

 : RMI Registgry : Listening on port 8999
2009-07-09 15:50:20 +0100 MESSAGE MNG-10021003 : :ting Startingdown : RMI ConnectorServerRegistgry : Listening on port 90998999
2009-07-09 15:50:20 +0100 MESSAGE MNG-10061003 : ting down Using: SSLRMI KeystoreConnectorServer : test_resources/ssl/keystore.jks Listening on port 9099
2009-07-09 15:50:20 +0100 MESSAGE MNG-10041005 : Ready

Shutdown

Stopped

VirtualHost

Virtualhosts cannot be programatically created so the log messages will have to be found during the startup/shutdown of the broker.

Startup

During startup the following VHT messages will be logged as the Virtualhost is created and its working directory specified.During shutdown the two listeners created during startup will shutdown. The use of SSL will no provide any additional shutdown mesasage to verify.

2009-07-09 15:50:20 +0100 MESSAGE MNG-1003[ vh:(test) ting] downVHT-1001 : RMI Registgry : Listening on port 8999 Created : test
2009-07-09 15:50:20 +0100 MESSAGE MNG-1003[ vh:(test) ting] downVHT-1002 : RMIWork ConnectorServerdirectory : Listening on port 9099/tmp

Shutdown

On shutdown the Virutalhost will only log that it has been closed.

2009-07-09 15:50:20 +0100 MESSAGE MNG-1005 +0100 MESSAGE [ vh:(test) ] VHT-1003 : StoppedClosed

VirtualHost

Virtualhosts cannot be programatically created so the log messages will have to be found during the startup/shutdown of the broker.

Startup

During startup the following VHT message will be logged as the Virtualhost is created and its working directory specified.

2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>) ] VHT-1001 : Created : <name>
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>) ] VHT-1002 : Work directory : <path>

Shutdown

MessageStore

The MessageStore details will be logged as part of the Virtualhost startup and shutdown.

Startup

Aside from the easy to test create(MST-1001) and store location(MST-1002) messages, a persistent store such as DerbyDB will also need to be used for testing so that the recovery messages MST-1004-6 can be tested.
It is expected that on recovery start MST-1004 will be logged without a queue name. Then as each queue is recovered then a start(MST-1004), count (MST-1005) and complete (MST-1006) will be logged. Only when all queues have been recovered will a final complete (MST-1006) be logged. This would give a sequence such as:On shutdown the Virutalhost will only log that it has been closed.

2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>) ] VHT-1003 : Closed

MessageStore

The MessageStore details will be logged as part of the Virtualhost startup and shutdown.

Startup

Aside from the easy to test create(MST-1001) and store location(MST-1002) messages, a persistent store such as DerbyDB will also need to be used in testing so that the recovery messagse MST-1004-6 can be tested.
It is expected that on recovery start MST-1004 will be logged without a queue name. Then as each queue is recovered then a start(MST-1004), count (MST-1005) and Complete (MST-1006) will be logged. Only when all queues have been recovered will a final complete (MST-1006) be logged.

test) ] MST-1001 : Created
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(test) ] MST-1001 : Created : DerbyMessageStore
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(test) ] MST-1002 : Store location : ./derbyDB
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-10011004 : CreatedRecovery :Start <name>
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-10021004 : StoreRecovery locationStart \[: <path>qu(myQueue)]
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-10041005 : Recovered Recovery100 Startmessages \[: <queue.name>]for qu(myQueue)
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-10051006 : RecoveredRecovery <count>Complete messages for queue <queue.name>\[: qu(myQueue)]
2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-1006 : Recovery Complete \[: <queue.name>] 

Shutdown

On shutdown the MessageStore will only log that it has been closed.

2009-07-09 15:50:20 +0100 MESSAGE [ vh:(<name>test) ] MST-1003 : Closed

Connection

...

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test) ] CON-1001 : Open : Client ID <id>client1 : Protocol Version : <version> 0-9
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test) ] CON-1002 : Close

Channel

As with connection Connection creation Channel creation can be tested in isolation. Whilst a channel will be created along with the connectionConnection. A new channel can be created from the Java client by creating a new JMS Session. The current Java client will start all Channels on the JMS Connections Connection flowed. This means that an intial initial 'CHN-1002 : Flow Stopped' message will be logged. Only when the JMS Connection is started will the Channel bun unflowed and a 'CHN-1002 : Flow Started' logged.

Additional testing should be done to ensure that CHN-1002 messages are logged when the client exceeds its prefetch count and the broker flows the client.

be logged. Only when the JMS Connection is started will the Channel bun unflowed and a 'CHN-1002 : Flow Started' logged.

Additional testing should be done to ensure that CHN-1002 messages are logged when the client exceeds its prefetch count and the broker flows the client.

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2 ] CHN-1001 : Create : Prefetch 500
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2 ] CHN-1002 : Flow Stopped
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2 ] CHN-1002 : Flow Started

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2 ] CHN-1001 : Create : Prefetch <count> CHN-1003 : Close

Queue

There are a number of properties that can be set on a Queue and as a reusult they all need to be tested in isolation and validated that the correct log message is generated based on this template:

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/qu(myqueue) ] CHN-1002 : Flow <value>
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/)/ch:2 ] CHN-1003 : Close

Queue

 \\ 
                          QUE-1001 : Create : [AutoDelete] [Durable|Transient] [Priority:<levels>] [Owner:<name>]

Property combinations to test:

• Durable | Transient
  • AutoDelete
  • Priority

This results in 6 tests as each Combination of AutoDelete|Priority|None is tested against Durable|Transient.

A simple deleted is logged when the queue is finally deleted.There are a number of properties that can be set on a Queue and as a reusult they all need to be tested in isolation and validated that the correct log message is generated based on this template:

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/)/ch:2/qu(myqueue) ] \\ 
                          QUE-1001 : Create : [AutoDelete] [Durable|Transient] [Priority:<levels>] [Owner:<name>]

Property combinations to test:

• Durable | Transient
  • AutoDelete
  • Priority

This results in 6 tests as each Combination of AutoDelete|Priority|None is tested against Durable|Transient.

 [ con:1(guest@127.0.0.1/test)/ch:2/qu(myqueue) ] QUE-1002 : Deleted

Exchange

As with Queue logging the Exchange has the Durable option that must be tested independently. During broker startup the default exchanges will be created and so will be logged. Testing should ensure that these log messages are indeed correctly logged.
However as Exchanges can be programatically declared this should also be testedA simple deleted is logged when the queue is finaly deleted.

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/qu(myqueue) ] QUE-1002 : Deleted

Exchange

As with Queue logging the Exchange has the Durable option that must be tested indpendently. During broker startup the default exchanges will be created and so will be logged. Testing should ensure that these log messages are indeed correctly logged.
However as Exchanges can be programatically declared this should also be tested.

ex(amq.direct) ] EXH-1001 : Create : Durable Type:amq.direct Name:amq.direct
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/ex(amq.direct) ] EXH-1001 : Create : [Durable]: Type:<value>amq.direct Name:<value> amq.direct
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/ex(amq.direct) ] EXH-1002 : Deleted

...

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/ex(amq.direct)/qu(myQueue)/rk(myQueue) ] \\ 
                          BND-1001 : Create [: Arguments : <key=value>]
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/test)/ch:2/ex(amq.direct)/qu(myQueue)/rk(myQueue) ] \\
                          BND-1002 : Delete

...

There are two types of subscription, durable and non-durable. The durable subscription can be tested from the Java Client by creating a JMS Durable Topic Subscription. Additionally both types of subscription can have an additional argument for the JMS selector. The non-durable subscription type can also operate as a JMS Queue Browser which has an additional 'autoclose' argument.

This makes 5 different possible Create (SUB-1001) log messages.

'autoclose' argument.

This makes 5 different possible Create (SUB-1001) log messages.

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/)/ch:2/sub:1:qu(myqueue) ] SUB-1001 : Create : Durable [Arguments : <key=value>]

2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/)/ch:2/sub:1:qu(myqueue) ] SUB-1001 : Create [: [Durable] [Arguments : <key=value>]
2009-07-09 15:50:20 +0100 MESSAGE [ con:1(guest@127.0.0.1/)/ch:2/sub:1:qu(myqueue) ] SUB-1002 : Close