Thursday, August 28, 2008

Tracing in NMS



It easy to turn protocol tracing on in NMS client.
First of all you need to implement your trace class. I am lazy so I wrote an adapter for log4net.


/*
* ----------------------------------------------------------------------------
* "THE BEER-WARE LICENSE"
* Vadim Chekan wrote this file. As long as you retain this notice you
* can do whatever you want with this stuff. If we meet some day, and you think
* this stuff is worth it, you can buy me a beer in return
* ----------------------------------------------------------------------------
*/

using System;
using log4net;
using Apache.NMS;

namespace NMSTestConsole
{
public class TraceAdapter : Apache.NMS.ITrace
{
// keep logs on behalf of NMS Tracer
static readonly ILog _log = LogManager.GetLogger(typeof(Apache.NMS.Tracer));

public bool IsDebugEnabled {
get {return _log.IsDebugEnabled;}
}

public bool IsInfoEnabled {
get {return _log.IsInfoEnabled;}
}

public bool IsWarnEnabled {
get {return _log.IsWarnEnabled;}
}

public bool IsErrorEnabled {
get {return _log.IsErrorEnabled;}
}

public bool IsFatalEnabled {
get {return _log.IsFatalEnabled;}
}

public void Debug (string message)
{
_log.Debug(message);
}

public void Info (string message)
{
_log.Info(message);
}

public void Warn (string message)
{
_log.Warn(message);
}

public void Error (string message)
{
_log.Error(message);
}

public void Fatal (object message)
{
_log.Fatal(message);
}
}
}


Now you need hook it up somwhere at the very beginning of your program.

using Apache.NMS;
using Apache.NMS.ActiveMQ;
...
Tracer.Trace = new TraceAdapter();
log4net.Config.BasicConfigurator.Configure();


That's it. Run your program which communicates to ActiveMQ and see the result.

Getting more info


There is not too much information right now. Output looks like:

Parsing type: 1 with: Apache.NMS.ActiveMQ.OpenWire.V1.WireFormatInfoMarshaller
Parsing type: 2 with: Apache.NMS.ActiveMQ.OpenWire.V2.BrokerInfoMarshaller
Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V2.ResponseMarshaller


Those numbers are ID of OpenWire packet types. Probably you would prefer something more human readable. You can achieve it by setting UseLogging property of TcpTransportFactory. The best wat of doing it is via broker url parameters:

IConnection conn = new ConnectionFactory("tcp://localhost:61616?transport.UseLogging=true").CreateConnection();



SENDING: WireFormatInfo[ Magic=System.Byte[] Version=2 MarshalledProperties={CacheEnabled=False, SizePrefixDisabled=False, StackTraceEnabled=False, TcpNoDelayEnabled=False, TightEncodingEnabled=False} ]
414 [-1225462896] DEBUG Apache.NMS.Tracer (null) - Parsing type: 1 with: Apache.NMS.ActiveMQ.OpenWire.V1.WireFormatInfoMarshaller
424 [-1225462896] INFO Apache.NMS.Tracer (null) - RECEIVED: WireFormatInfo[ Magic=System.Byte[] Version=3 MarshalledProperties={CacheEnabled=True, CacheSize=1024, SizePrefixDisabled=False, TightEncodingEnabled=True, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000, StackTraceEnabled=True, TcpNoDelayEnabled=True} ]

SENDING: ConnectionInfo[ ConnectionId=ConnectionId[ Value=2957a0f0-a8b7-4abc-96ea-e5638b6d0baa ] ClientId=49b903c4-f55e-40b0-a78c-bde850b77ef8 Password= UserName= BrokerPath= BrokerMasterConnector=False Manageable=False ClientMaster=True ]
453 [-1225462896] DEBUG Apache.NMS.Tracer (null) - Parsing type: 2 with: Apache.NMS.ActiveMQ.OpenWire.V2.BrokerInfoMarshaller
463 [-1225462896] INFO Apache.NMS.Tracer (null) - RECEIVED: BrokerInfo[ BrokerId=BrokerId[ Value=ID:ubuntu-47413-1219891509239-0:0 ] BrokerURL=tcp://ubuntu:61616 PeerBrokerInfos=Apache.NMS.ActiveMQ.Commands.BrokerInfo[] BrokerName=localhost SlaveBroker=False MasterBroker=False FaultTolerantConfiguration=False DuplexConnection=False NetworkConnection=False ConnectionId=0 ]
463 [-1225462896] DEBUG Apache.NMS.Tracer (null) - Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V2.ResponseMarshaller
463 [-1225462896] INFO Apache.NMS.Tracer (null) - RECEIVED: Response[ CorrelationId=1 ]
474 [-1211062496] INFO Apache.NMS.Tracer (null) - SENDING: SessionInfo[ SessionId=SessionId[ ConnectionId=2957a0f0-a8b7-4abc-96ea-e5638b6d0baa Value=1 ] ]
475 [-1225462896] DEBUG Apache.NMS.Tracer (null) - Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V2.ResponseMarshaller
475 [-1225462896] INFO Apache.NMS.Tracer (null) - RECEIVED: Response[ CorrelationId=2 ]



Now you can have much better idea what your client is chatting about with the server.

2 comments:

James Strachan said...

Cool - maybe we should add a log4net tracer implementation to the NMS codebase?

Paul Lockwood said...

Worked great, thanks!