Girish Jain on .Net Framework

I will be writing about my favorite technology which is Microsoft .Net Framework and how to use it to improve developer productivity

Intercept raw SOAP Message

clock April 3, 2012 21:26 by author Girish Jain

Intercept raw SOAP Message

Download source code - SOAPExtensionsLib.zip (8 kb)

While working with web services, often there are situations when you want to extract the raw SOAP message coming in to and going out of your web service. This is specially the case when you are exposing a web service and the client application is not written by you but some other company and you want to debug a scenario such as when the incoming message is not getting de-serialized to object instance, namespace issues, and so on. If you are writing your web service in ASP .Net then good news is that it is very much possible to intercept the raw SOAP message. In fact, you can work with these raw SOAP messages and do some additional works such encrypt/decrypt its contents, modify message header details, and so on. All this is possible by creating a SOAP extension which can be plugged into HTTP pipeline of ASP .Net engine.

You will find many articles on internet which tell you how to write a SOAP extension and different possibilities that can be achieved with it. But if you are like majority of developers, you just want to get raw SOAP message and want the bare minimum implementation to achieve the same, and I did not find a simple implementation for this purpose with my google skills so I decided to write one myself, of course with the help of other articles which I found on internet.

I am essentially after a very basic functionality which logs the raw SOAP message to a configured trace listener, and that is exactly what I am going to show you as part of this post. I am going to write a SOAP extension which will intercept the raw SOAP message and log it. The logging destination is to be chosen by you by adding a trace listener to the application so you don’t have to modify the SOAP extension if you choose a different logging destination and so on. You can choose to log to a file, event log, database table, etc, take your pick.

The incoming SOAP message is relatively easy to intercept and requires far less code whereas intercepting outgoing SOAP message requires relatively more work. To keep the matter simple I am going to create a SOAP Extension Library project and write two separate extensions, one which intercepts just the incoming SOAP message and the second one which intercepts incoming as well as outgoing SOAP message.

Below diagram explains the SOAP message processing extremely well. As part of creating a new SOAP extension we will need to override ProcessMessage method, which is invoked for four different stages of message processing. We will also need to override few more methods which are defined as abstract in the base SoapExtension class such as ChainStream.

SOAP Request Handling

Source: http://msdn.microsoft.com/en-us/magazine/cc164007.aspx

As we can see in above diagram, ChainStream method will be called twice in the lifecycle of SOAP message processing, first BEFORE the actual web service method is called and second time AFTER the web method call is finished. This method provides us with an opportunity to chain a new stream instance based on our requirements. Let’s see it in action with two new SOAP extensions.

Intercept Incoming SOAP Message

In case of incoming SOAP message, the stream initialized by .Net framework is accessible and you can reset the position (i.e. CanSeek property returns true). Hence, we don’t really need to chain another stream instance and can reuse the same. Find below its implementation:

using System;
using System.Collections.Generic;
using System.Text;
using System.Web.Services.Protocols;
using System.IO;
using System.Diagnostics;

namespace SOAPExtensionsLib
{
    public class IncomingSOAPMessageInterceptExtension : SoapExtension
    {
        public override Stream ChainStream(Stream stream)
        {
            // ChainStream method is called twice in the lifecycle of the SOAP
            // message processing. BEFORE the actual web service operation is
            // invoked and AFTER it has completed. 
            // 
            // In case you just want to intercept the incoming SOAP message then
            // you can read the stream initialized by .Net framework and hence, 
            // you dont need to chain a new stream. Therefore, pass the same 
            // stream back.
            //------------------------------------------------------------
            return stream;
        }

        public override object GetInitializer(Type serviceType)
        {
            return null;
        }

        public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
        {
            return null;
        }

        public override void Initialize(object initializer)
        {
            // do nothing...
        }

        public override void ProcessMessage(SoapMessage message)
        {
            switch (message.Stage)
            {
                case SoapMessageStage.BeforeDeserialize:
                    // Incoming message
                    LogMessageFromStream(message.Stream);
                    break;

                case SoapMessageStage.AfterDeserialize:
                    break;

                case SoapMessageStage.BeforeSerialize:
                    break;

                case SoapMessageStage.AfterSerialize:
                    break;
            }
        }

        private void LogMessageFromStream(Stream stream)
        {
            string soapMessage = string.Empty;

            // Just making sure again that we have got a stream which we 
            // can read from AND after reading reset its position 
            //------------------------------------------------------------
            if (stream.CanRead && stream.CanSeek)
            {
                stream.Position = 0;

                StreamReader rdr = new StreamReader(stream);
                soapMessage = rdr.ReadToEnd();


                // IMPORTANT!! - Set the position back to zero on the original 
                // stream so that HTTP pipeline can now process it
                //------------------------------------------------------------
                stream.Position = 0;
            }

            // You have raw SOAP message, log it the way you want. I am using 
            // Trace class as I have configured a trace listener which will 
            // write it to a database table, read:
            // http://girishjjain.com/blog/post/Advanced-Tracing.aspx
            //------------------------------------------------------------
            Trace.WriteLine(soapMessage);
        }
    }
}

You just need to make couple of changes to your web.config file, to make the extension work

1. In order to enable the new SOAP extension, you need to add it to soap extensions list using following:

2. You need to add a trace listener as follows (I am using a custom database trace listener but feel free to use anything else like EventLogTraceListener, TextWriterTraceListener, etc):

That’s it, a simple SOAP extension which logs every incoming SOAP message to a configured trace listener. Voila!

Intercept Incoming & Outgoing SOAP Message

Now if you want to intercept output SOAP message as well then, there is little more work needed to be done in the SOAP extension and hence, I have created a separate extension for the purpose. In case of incoming SOAP message, the stream instance created by ASP .Net engine is read-able so you can access it, read its contents, reset position, etc. whereas, in case of outgoing SOAP message (web service method response), the output stream created by ASP .Net engine is an instance of SoapExtensionStream class which does NOT support read operations but write only. Essentially speaking, you cannot read output stream contents but you can write to it. Hence, in this case we need to chain a new memory stream which we can read from and will pass this memory stream instance to HTTP pipeline to process the message and capture web service method response, and once done we will read its contents (SOAP response) and copy its contents to the original stream created by ASP .Net engine (of type SoapExtensionStream). Find below its code:

using System;
using System.Collections.Generic;
using System.Text;
using System.Web.Services.Protocols;
using System.Diagnostics;
using System.IO;

namespace SOAPExtensionsLib
{
    public class IncomingOutgoingSOAPMessageInterceptExtension : SoapExtension
    {
        Stream _originalStream;
        Stream _workingStream;

        public override Stream ChainStream(Stream stream)
        {
            // ChainStream method is called twice in the lifecycle of the SOAP
            // message processing. BEFORE the actual web service operation is
            // invoked and AFTER it has completed. 
            //
            // In case of outgoing response, .Net framework initializes a stream
            // as an instance of type SoapExtensionStream which does NOT support
            // reading from but write operations only. Therefore, we will chain
            // a local stream instance which will be passed to for processing by
            // actual web service method and will be read from when web service
            // method finishes processing. 
            //
            // Therefore, we need to copy contents from original stream to
            // working stream instance before 
            // Once we have read outgoing SOAP message, we will write contents 
            // from working stream to the original (SoapExtensionStream) instance, 
            // for HTTP pipeline to return it to caller.


            // Store reference to incoming stream locally
            _originalStream = stream;

            // Create a new working stream to work with
            _workingStream = new MemoryStream();
            return _workingStream;
        }

        public override object GetInitializer(Type serviceType)
        {
            return null;
        }

        public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
        {
            return null;
        }

        public override void Initialize(object initializer)
        {
            // do nothing...
        }

        public override void ProcessMessage(SoapMessage message)
        {
            switch (message.Stage)
            {
                case SoapMessageStage.BeforeDeserialize:
                    // Incoming message
                    Copy(_originalStream, _workingStream);
                    LogMessageFromStream(_workingStream);
                    break;

                case SoapMessageStage.AfterDeserialize:
                    break;

                case SoapMessageStage.BeforeSerialize:
                    break;

                case SoapMessageStage.AfterSerialize:
                    // Outgoing message
                    LogMessageFromStream(this._workingStream);
                    Copy(this._workingStream, this._originalStream);
                    break;
            }
        }

        private void LogMessageFromStream(Stream stream)
        {
            string soapMessage = string.Empty;

            // Just making sure again that we have got a stream which we 
            // can read from AND after reading reset its position 
            //------------------------------------------------------------
            if (stream.CanRead && stream.CanSeek)
            {
                stream.Position = 0;

                StreamReader rdr = new StreamReader(stream);
                soapMessage = rdr.ReadToEnd();
                

                // IMPORTANT!! - Set the position back to zero on the original 
                // stream so that HTTP pipeline can now process it
                //------------------------------------------------------------
                stream.Position = 0;
            }

            // You have raw SOAP message, log it the way you want. I am using 
            // Trace class as I have a configured a trace listener which will 
            // write it to database table
            // http://girishjjain.com/blog/post/Advanced-Tracing.aspx
            //------------------------------------------------------------
            Trace.WriteLine(soapMessage);
        }

        private void Copy(Stream from, Stream to)
        {
            TextReader reader = new StreamReader(from);
            TextWriter writer = new StreamWriter(to);
            writer.Write(reader.ReadToEnd());
            writer.Flush();
        }
    }
}

Feel free to use the extension depending upon your requirements, all that you would need to do is place the dll in the bin folder and make couple of changes to web.config file and you are done, absolutely no changes required to your application. Simple implementation for intercepting raw SOAP messages, that’s what I was after to begin with.

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




Tracing with Code Injection

clock December 2, 2011 02:17 by author Girish Jain

Source: http://valuestockphoto.com/downloads/14852-2/needle_injection.jpg

Continuing from one of my previous blog post on advanced tracing, today I am going to talk about going to the next level of tracing, which is using code injection to insert tracing calls in method body. CLR assembly files (dll or exe) have a very well documented file format/structure (Standard ECMA-335 Common Language Infrastructure), which makes it possible for tools to inspect the code (such as reflector tool) or inject the code using Reflection or other API/libraries such as Mono.Cecil.

Download entire source code (167 KB)

Requirement/Need

After our application goes live, we get lot of support calls; this is especially true for large distributed applications. Support team attempts to reproduce the scenario in dev environment, debug through the code, and finds root cause of the issue. They find the issue and fix it, happy days!

But that’s not how it always turns out to be in reality. For those who have developed the application AND then supported the same in live as well, know that very well. Sometimes (unfortunately), support team or the developer is not able to reproduce the scenario in dev environment as there will be many external/data dependencies which they cannot reproduce in dev environment. The developer tries his best to go through the code with assumed data values, assuming how the method would have executed, and so on. If lucky, he finds it soon, otherwise, he struggles a lot but eventually finds the root cause and provides the fix.

How about a situation where we can turn tracing on for an application at runtime and it starts writing all the information that a developer needs, most important of all being the code execution flow i.e. the sequence of methods which were executed at a point in time. If developer had this information at hand, it will make his life very easy in fault finding. Remember, tracing offers great advantage such that you can selectively turn it on or off at application/service level and you can filter the trace information as well using trace switches. You can define following values for a given trace switch: Off, Error, Warning, Info, and Verbose. This helps you control the information that gets logged to trace destination from your application.

 

Manual solution and its constraints

One solution to this requirement would be that we insert a tracing call at the start of each method as follows:

    private void DisplayProcessedInformation(bool pblnStartUp)
    {
    Trace.WriteLine(string.Format("{0} : {1} invoked", DateTime.Now.ToString(), "System.Void MyNamespace.ClassName::DisplayProcessedInformation(System.Boolean)"));
    // Method logic continues ...
    }
    

And if you are using DBTraceListener from previous post then it will log an entry to tracelog table in database each time the method executes, as follows:

<TraceLog> <Message>23/11/2011 17:17:33 : System.Void MyService.NavisionUpdate::DisplayProcessedInformation(System.Boolean) invoked</Message> </TraceLog>

As you can see, above trace entry tells developer the exact time a particular method was invoked. Now imagine, manually writing one line of extra code in each method with the correct method signature as its data. You ask your developers to do this and the very next day they will come back and tell you it’s not feasible. J

We don’t want to write the code ourselves to call the Trace.WriteLine method in all the methods across entire application and all libraries, as that would be a lot manual work and it will be very difficult (almost impossible) to maintain consistency across the entire codebase. The quality of trace information being written to configured trace destination will depend upon the developer. For example, one developer will write method name, other will write the signature partially, third one will not write method return type, and so on. There will be hundreds of possible ways to write one piece of trace information and it will be dependent upon the developer, which one he chooses.

Let’s not be dependent upon the developer for the reasons mentioned above. Let’s automate the step of writing one piece of information to trace destination i.e. the method signature as the method executes.

 

Code Injection Approach

What if, we don’t ask developers to write any additional code for tracing but only to mark each method with a certain attribute? And methods marked with that attribute will automatically be logged to trace destination each time they are executed (of course, only if tracing is turned on and trace level is set to Verbose). Tell this to your developers and they will love you. J That’s what I am going to do as part of this post. I am going to write a console application which takes a CLR assembly as input, traverses through all its types and their methods and checks for a custom attribute on each method. For a method marked with the custom attribute, this application will inject some code so that it will write to the trace destination whenever that method gets executed.

 

Actual code

Reflection API is available as part of .Net framework (System.Reflection and System.Reflection.Emit namespaces) but it is not so simple and straight forward to work with. At the same time, Mono.Cecil project overcomes the complexities of Reflection APIs and makes it possible for you to inject code into existing CLR assemblies (dll or exe) very easily. Hence, I have decided to use Mono.Cecil for the purpose.

The TraceInjection class and its InjectTracingLine method contain crux of this application. Its logic is as follows:

  1. Loads the input assembly

  2. Loops over all its modules

  3. For each module, loops over all its types

  4. For each type, loops over all its methods

  5. For each method, checks whether it is marked with LogMethodExecutionEntryAttribute custom attribute

  6. If method is marked with custom attribute, then inject following two IL instructions at the start of method body

     a. ldstr <method signature> // Loads (pushes) method signature string on to the evaluation stack

     b. call AdvancedTracing::Utility::WriteTraceLine method // Pops the method signature from the evaluation stack and passes it to WriteTraceLine method as argument

  7. Saves modified assembly back to disk

The injected code calls the WriteTraceLine method which is defined in Utility class of AdvancedTracing library and it simply calls the Trace.WriteLine method as follows:

    static public void WriteTraceLine(string methodName) {
    Trace.WriteLine(string.Format("{0} : {1} invoked", DateTime.Now.ToString(), methodName));
    } 

Mono.Cecil library has ILProcessor class which lets you generate IL code i.e. create Instruction instances, which are then inserted into method body. The IL code injected by CodeInjection application leaves the evaluation stack in a clean state i.e. the new values “pushed” onto the stack are “popped”. After the injected IL instructions are executed, stack is in similar state to how it was when the method execution had actually begun.

Here’s the entire code for TraceInjection class:

using Mono.Cecil;
using Mono.Cecil.Cil;
using System.Configuration;
using System.IO;
using System.Diagnostics;

namespace CodeInjection
{
    class TraceInjection
    {
        public bool InjectTracingLine(string assemblyPath, string outputDirectory)
        {
            CustomAttribute customAttr;
            AssemblyDefinition asmDef;

            // New assembly path
            // moved to new overload
            //string outputDirectory = ConfigurationManager.AppSettings["OutputDirectory"].ToString();
            string fileName = Path.GetFileName(assemblyPath);

            string newPath = outputDirectory + @"\" + fileName;

            // Check if Output directory already exists, if not, create one
            if (!Directory.Exists(outputDirectory))
            {
                Directory.CreateDirectory(outputDirectory);
            }

            try
            {
                // Load assembly
                asmDef = AssemblyDefinition.ReadAssembly(assemblyPath);

                foreach (ModuleDefinition modDef in asmDef.Modules)
                {
                    foreach (TypeDefinition typDef in modDef.Types)
                    {
                        foreach (MethodDefinition metDef in typDef.Methods)
                        {
                            // Check if method has the required custom attribute set
                            if (this.TryGetCustomAttribute(metDef, "AdvancedTracing.LogMethodExecutionEntryAttribute", out customAttr))
                            {
                                // Method has the desired attribute set, edit IL for method
                                Trace.WriteLine("Found method " + metDef.ToString());

                                // Get ILProcessor
                                ILProcessor ilProcessor = metDef.Body.GetILProcessor();

                                // Load fully qualified method name as string
                                Instruction i1 = ilProcessor.Create(
                                OpCodes.Ldstr,
                                metDef.ToString()
                                );
                                ilProcessor.InsertBefore(metDef.Body.Instructions[0], i1);

                                // Call the method which would write tracing info
                                Instruction i2 = ilProcessor.Create(
                                OpCodes.Call,
                                metDef.Module.Import(
                                typeof(AdvancedTracing.Utility).GetMethod("WriteTraceLine", new[] { typeof(string) })
                                )
                                );
                                ilProcessor.InsertAfter(i1, i2);
                            }
                        }
                    }
                }

                // Save modified assembly
                asmDef.Write(newPath, new WriterParameters() { WriteSymbols = true });
            }
            catch
            {
                // Nothing to be done, just let the caller handle exception
                // or do logging and so on
                throw;
            }

            return true;
        }

        public bool InjectTracingLine(string assemblyPath)
        {
            // New assembly path
            string outputDirectory = ConfigurationManager.AppSettings["OutputDirectory"].ToString();
            return this.InjectTracingLine(assemblyPath, outputDirectory);
        }

        public bool TryGetCustomAttribute(MethodDefinition type, string attributeType, out CustomAttribute result)
        {
            result = null;
            if (!type.HasCustomAttributes)
                return false;

            foreach (CustomAttribute attribute in type.CustomAttributes)
            {
                if (attribute.Constructor.DeclaringType.FullName != attributeType)
                    continue;

                result = attribute;
                return true;
            }

            return false;
        }
    }
}
    

And the LogMethodExecutionEntryAttribute is defined as follows:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

namespace AdvancedTracing
{
    [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = true)]
    public class LogMethodExecutionEntryAttribute : Attribute
    {
    }
}
    

How-to Use it

It is very simple to use CodeInjection application with your existing projects. You need to follow the following steps:

  1. Add reference to AdvancedTracing library in your project (This is the project which contains definition of LogMethodExecutionEntryAttribute class in in my case and a custom database trace listener implementation as well. But you can choose to use your own trace listener and create your own project)

  2. Mark method which you wish to be code injected with LogMethodExecutionEntryAttribute attribute.

  3. Add a post-build action for your project under project property as follows (under Compile tab, click on Build Events button):

project post-build event example

The CodeInjection.exe takes assembly file and the output directory as arguments. Code injected assembly will be dropped at the output directory specified. The %CD% specifies current directory, as argument value for output directory parameter.

  4. You need to add a trace listener to your application configuration file. If you want to log trace data to database table then you can use below configuration example (for detailed steps and script for DB trace listener refer the Advanced Tracing post) :

tracing configuration example

Important!

  1. Please note that this application uses Mono.Cecil library which is freely available but I needed to copy its copyright and permission notice to the source code folder. If you use this application or its source code, make sure to copy the same notice to your application as well.

  2. Although, CodeInjection application also generates a PDB file for debugging purpose but, for some reason (don’t know why) it has never worked for me. Therefore, for debugging, I always use the DLL and PDB generated by Visual Studio minus injected code.

In some future post, I will improve the code injection application and log to trace destination all the data passed to methods as well i.e. argument values for method parameters.

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share quick posts, tips, links, etc. My Twitter handle is: @girishjjain

 

[Edit] Please read part II of this series of blog post here, wherein I have improved the code injection application to inject code to method body such that it logs method parameters values as well. Also, the source code has been updated and few bugs fixed.



Mandatory fields Validation

clock November 1, 2011 22:38 by author Girish Jain

clip_image002

Image Source: http://www.velojoy.com/2011/02/28/how-to-avoid-having-to-steal-your-own-bike/crying_baby/

Today I am going to talk about user experience of an application and the most common pitfall in application UI design which brings disrepute to applications. It’s about validations on screens in your application. The most notorious example of validations on UI is mandatory/required field validation. It is the most common validation on data entry screens, where large numbers of fields are marked as mandatory. This mostly happens on master data entry screens but at times transaction screens fall prey to this as well. In reality, you don’t need majority of those fields, which are marked as mandatory, to really be mandatory. Some of the fields are captured for reporting purpose and does not have any significance in transaction processing.

Let’s take an example of a master entry screen where a mandatory field becomes a hindrance. In case of a job management system, you are trying to setup a new engineer but this has a mandatory field for supplier branch from where engineer would collect his stock items. At the time of setting up a new engineer, you would not necessarily know about the new supplier branch. Now imagine new engineer setup screen being a multi-tabbed input screen and supplier branch field being on the second or third tab. You have entered all the input fields on the first and second tab and on the third tab you realize that you cannot provide value for supplier branch. If you cancel it now, you will lose all the input entered on the first and second tab and will have to enter it all again but that’s the only option left because it won’t let you save the entry minus supplier branch and supplier branch dropdown is empty because you need to perform another set of steps to define a new supplier branch for an area. See how the objects in the system are so tightly related and have a dependency on one another.

While setting up a new engineer in system, having a supplier branch associated is not that mandatory. System should not really make it a mandatory field. When we design systems in this fashion, users cry foul and term it as, system limitation. It’s not the best of the system design or user experience either.

Almost (99% of) all the times, user will have all the data handy to complete data entry on a screen but there would be times when user would want to partially complete the entry and at some later stage provide data for rest of the fields. There would be real-life practical scenarios requiring partial save. Users are not allowed to save partial data entry as more number of fields are mandatory than the data available with the user.

Our approach should be to keep least number of input fields as mandatory, which would cater to 100% of situations.

For example, when adding a new supplier master entry, user may not have details like Fax # or email address but he would still want to save the new supplier minus these details. Developer would argue that at some point these details would be used (for sending fax or email from system) and hence, they need to collect it from user while saving the entry itself, (that’s where the problem lies). True, they need to have those inputs from user for some further processing but, not necessarily while saving the master entry itself. User could always come back at some later stage and update the missing fields.

We design UI so as to secure maximum possible information at the time of first save itself, so that we can safely assume that this data would be available whenever we need to actually use it (and it would not be having value NULL in DB table). Instead of assuming, applications should rather check for required data availability and, if any required data is missing then let the user know. This way we can avoid forcing the user to enter all the data in one go on initial data entry screen and allow partial save.

Next time you design a new UI screen, think twice before deciding to define a field as mandatory. Simple rule would be to keep the least number of input fields as mandatory. Keep a field as mandatory, only if it really is mandatory.

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




System Validation aka Business Rule

clock October 13, 2011 00:18 by author Girish Jain

When designing a system, normal tendency of business analyst (a person who is collecting requirements from client) (BA) is to define all the possible business validations that system needs to implement. The idea is to prevent user from accidentally performing an invalid operation which would not align with normal business practice or be against it. In the process of building the list of all these business validations, BA essentially identifies two types of rules. There are ones which are essentially required by client to ensure smooth running of business by its people and prevent them from making an absolute invalid transaction (or commit fraud). These are basic checks and balances which MUST be in place. These are usually very explicit from customer’s requirements. Then there are others, which are theoretical in nature and are not essentially required to be implemented by system, as these would almost never really be triggered in practice (you could argue that some of these would occur, but usually that’s more in theory and less in practice). These validations are usually not explicit from client’s requirements but added by BA (probably to show that he has given due consideration to client’s requirements and identified all business rules).

In the process of designing system, analysts usually make a big assumption that the end users of the system would be EITHER some brainless people who need to be taken care of at every stage and hence, they need to build every possible check into system OR they are some expert users who would try to take application/business for ride by performing a malicious transaction and hence, they need to prevent them from doing so. There lies the grave problem. Both these assumptions are incorrect and, they create more problem than they solve. Going for either of the extremes would not help, we should strike a balance between essential validations and optional (nice to have) validations by doing cost-benefit analysis.

 

Essential Validations

This category of validations MUST be implemented by system, let’s see examples of this to better understand this category. We call these as business rules and these MUST be implemented by system:

1. In case of scheduling system, you cannot assign a job to an engineer after his shift ends.

2. In case of a passenger check-in system, it should not allow passenger check-in if his name figures in the list of terrorists. (A very important validation rule these days J)

3. A customer, holding plumbing policy from insurance company, should not be allowed to raise claim for other types of damage to house, say glass and locks repair.

 

Theoretical Validations

For an inventory management application, it need not have a validation to ensure that the stock-in-hand quantity is not going into negative for a given product. In theory, this is a correct validation rule but in practice there would be number of situations which would cause the system to be out of sync with reality, resulting in an incorrect quantity being reported by system. In such a situation, if it is blocking a stock decrement transaction saying there is not enough quantity in hand, it is only ballooning the problem and making itself (application) less reliable. Often, such issues get into a snow-ball effect and make a far bigger mess to clean up.

Note: The above conclusion is based on understanding that in most cases, IT systems do not cater to ALL of the real-life scenarios but majority of the scenarios. Software applications mature over a period of time as new features are added, and existing functionality improved to align it with the business realities.

 

Cost of implementing validation rules

We invest lot more effort and time into thinking what all checks system needs to have so that user does not make a mistake or system does not allow user to make one. We document all these and these so called validations are then implemented by developers with great effort and a lot of time is spent by these developers for testing all these so called business validations. Then system tester writes all his system test scenarios for further validations based on the checks defined and spends great deal of time testing and certifying that application is working as per the validations defined.

Hence, it calls for doing a careful cost-benefit analysis for every business rule to determine whether one should be implemented.

 

Classic Example

Let me present another classic example of validation rules related discussion. Recently, while working on a web application, which had a complaints page where user could enter number of complaints for an engineer, I came across following discussions:

1. Should we restrict user and not allow entering number of complaints as zero?

2. What if user enters number of complaints as greater than zero but later goes and edits the number to zero, do we need to restrict it there?

In my opinion, as long as your processing logic, which is working on number of complaints, is correctly considering and processing the value zero and is not affected with sheer presence of a record with value as zero for a given engineer, why bother for all this? Following wastage occurs:

1. Business Analyst documents the validation check as a requirement.

2. Developer spends time on implementing the rules around it (on Add and Edit page)

3. Tester would write test cases for testing the same with boundary value analysis and so on.

At the end of this exercise of building smartness into your application, what is achieved? Absolutely nothing, we just implemented a validation rule in system which, in practice has almost zero chances of being triggered and, had it not been implemented, we would have lost nothing.

 

Data Integrity as Alternative

There is a concept called as data integrity, which is heavily under utilized or not understood by developers and analysts both. Developers need not implement every validation rule in UI screen; they should take advantage of data integrity rules supported by RDBMS and well design databases. A data integrity constraint defined at DB level guarantees correctness of data all the time and has a far lesser cost of implementation as compared to implementing validation rule in UI. Please note, I am not saying to replace UI validation rules with data integrity (CHECK) constraints but in certain situations, we can effectively use data integrity constraints.

 

Summary

1. There is a huge cost associated with a validation rules defined as part of business requirements. Hence, one should be aware of this cost and accordingly do the cost-benefit analysis to decide whether a particular validation rule should be implemented by system.

2. Do not spend too much of time and energy on building validation rules into the system but on adding features and functionality.

3. Remember, systems are meant to assist humans and not replace humans by defining all the validations and business rules and enforcing these.

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




Advanced Tracing

clock April 26, 2011 18:35 by author Girish Jain

Download source code (8 KB)

Objective of this article is to show how easy it is to get information from your running application and how you could store the same in a destination of your choice with very little development, making it easier for you to query available information and assist in diagnosing live system issues. We will start with basic understanding of Tracing with an example and then move on to the concept of advanced tracing.

Tracing provides a way to instrument your running application. It helps you trace code execution and you can emit information from your code during execution. Let us try to build a small application to understand the benefits of tracing. The two most important classes of concern to us from application code perspective is Debug and Trace, both are in System.Diagnostics namespace, former is mainly for debug build and latter for release build of your application.

To understand tracing in .Net Framework, let’s use most basic application which greets user, every programmer’s favorite Hello World!

using System;
using System.Diagnostics;

public class BasicTracingSample
{
      public static void Main()
      {
            Trace.WriteLine("Program execution started...");

            Console.WriteLine("Enter your name :");
            string strName = Console.ReadLine();

            Console.WriteLine(string.Format("Hello {0}!", strName));

            Trace.WriteLine(string.Format("Greeted User {0}", strName));
            Trace.WriteLine("Program finished...");

            Console.ReadLine();
      }
}

And let’s define the tracing settings for above program using application configuration file as follows:  

Compile the above application and execute it using the following commands:

Note that you have to define the TRACE constant as part of compilation for tracing to work. When working with projects in Visual Studio, you can achieve this using project property page under Build tab as follows:

Let’s now execute the application. You would notice that as part of the execution, it has created a log file with following contents:

In summary, using application configuration file and Trace.WriteLine method calls in code, we were able to get information from executing application to a log file. In our case, information was logged to a log file because we chose the TextWriterTraceListener If we use EventLogTraceListener provided by .Net Framework, it would start logging to windows event viewer. So you can choose your own logging destination by selecting trace listeners provided by .Net Framework.


Trace Methods

Trace class offers following methods which can be used for emitting information during application execution:

  1. Write

  2. WriteLine

  3. TraceInformation

  4. TraceWarning

  5. TraceError

These methods are tracing framework API for your application to simply call a relevant Trace method and the configured TraceListener would take care of dumping information to its known destination. These different methods help in determining the type of trace and additional information for that type so that trace listener can accordingly log it. For example, in case of EventLogTraceListener, it will log the type i.e. information, warning, or error as a value in “Type” column so that you can easily filter on it. It is basically for the trace listener implementation class to make best use of the information passed to it. These methods also use the trace switch defined for the trace listener in determining whether to log the trace. Let’s understand trace switches.


Trace Switches

The following table defines possible trace switches and how they affect trace output:

Enumerated value Integer value Type of message displayed (or written to a specified output target)
Off 0 None
Error 1 Only error messages
Warning 2 Warning messages and error messages
Info 3 Informational messages, warning messages, and error messages
Verbose 4 Verbose messages, informational messages, warning messages, and error messages

Source: http://msdn.microsoft.com/en-us/library/aa983740(v=vs.71).aspx

Trace switch gives you further ability to filter for only relevant information that you are interested in. During different stages of an application, you may want to switch between different switch values to control the output. For example, when a new application goes live for the first time, you may want to set the trace switch as Verbose so that you capture all the information but once the application has been stable for some time and you are not interested in logging all the information coming out of your application, then you may set the trace switch as Warning, and so on. And best part of it is that you can configure all this with application configuration file changes and you don’t need to recompile your application.


Need Something More

So far so good but we need something more! You have choice of using listeners available as part of .Net Framework such as ConsoleTraceListener, TextWriterTraceListener, EventLogTraceListener, XmlWriterTraceListener and so on. All these existing trace listeners are very good for some small application but for a large distributed application, you need a more robust approach for collecting and processing information (*making any good out of it*) from your executing application. Trace listeners provided by .net framework log to destinations which are not ideal for most distributed applications as functionality is spread across multiple applications, several components running on different servers across server estate and your application is logging large amount of information, which mostly is the case in a large distributed application. It becomes very difficult to search for information in a text file or event viewer, or group related information. Let’s take the most common requirement, say you want to search all the information logged for a particular transaction based on the transaction number or some other identifier for it. It would not be easy to extract such information from a text file or event viewer as the information that you are looking for would be scattered throughout the file/event viewer making it difficult to extract the real information you need.

To add to the woes, you need to work out your own approach for maintaining these destinations such as periodically moving the log files to some backup store and so on. Basically, we need a tracing solution which:

  1. Supports logging all the information from multiple applications to a central destination

  2. Provides ability to query the information in as simple manner as a database table (select, filter, sort, group, and so on)

  3. Provides an easy approach for maintenance of the logging destination

When I thought of such requirements for tracing solution, the immediate response was logging to a database table. If we are able to log trace information from an application to a database table then it meets all of the above requirements.


Custom Trace Listener to Rescue!

And a custom trace listener comes to the rescue! Tracing offers a pluggable framework for .Net applications to log information during execution. By pluggable, I mean you can add your custom trace listeners and provide your custom implementation of where you want to log the information and how. For example, you can write a custom trace listener to dump information to a table in database.

There are few major advantages of using a database table as logging destination, such as:

  1. It provides ability to use all DBMS constructs to query, filter, and summarize the information available. It is as good as any other transaction table and you can use the information available in the best possible manner.

  2. Maintenance becomes much easy with DB tables such that you can delete rows with unwanted information by simply writing a query. You can easily identify rows with unwanted data and delete these selectively. Alternatively, you can also schedule a DB job which deletes information more than 3 months old, etc. And many similar possible approaches as you would otherwise use with a database table.


There are some disadvantages of using a database table as logging destination and hence, it would not be a recommended approach if:

  1. Your application is emitting a LOT of information in a very short span of time as it would cause lot of database hits in very quick succession and may affect database performance, network bandwidth, and in turn your application performance.

  2. There is any kind of latency involved in accessing database such as network latency as it could be overburdening an already slow network and result in underutilization of network resources for core business purpose and could affect overall performance of your application and network.

You should measure performance of your application with respect to database and consider above factors before deciding to use database table as a destination for tracing. Also, since you can use multiple trace listeners for your application, you can decide to switch between these available trace listeners as and when required and make the best use of their features for diagnosing the issue and you don’t need to recompile your application either. You can control the trace listeners for application from the configuration file itself but for certain types of applications, you may need to restart the application for trace listener changes in configuration file to take effect.

Let’s move on to start designing a custom database trace listener and them its implementation.


Design Considerations

Let’s design the table in which we will log all our trace entries:

tracelog
PK traceid int identity
message xml
type varchar Default 'Verbose'
componentname varchar Default NULL
loggeddate datetime Default getdate()

Let’s highlight key requirements that this custom DB trace listener should support:

  1. To be able to categorize the information coming from application properly instead of dumping it all as part of a long string (and you are not sure where one part ends and other begins as your eye ball takes effort to scan it slowly). We need something like XML tree where each element represents certain information which can be easily identified and searched upon.

We define the data type of the message column in our table as XML and trace listener implementation to take care of converting the information coming its way into an XML string

  2. To be able to define connection string for the database in configuration file

This can be defined as part of initializeData attribute already supported on trace listener in application configuration file and we would be supporting an additional attribute for this purpose as well namely connectionString.

  3. It should provide the ability to assign an identifier at application/service level to trace entries so that you can filter/group entries from one same application

Trace listener implementation would support an additional attribute namely componentName which can be defined in the application configuration file to separately identify all the trace entries from an application. The value defined for this attribute would be stored in the componentname column in table

  4. Ability to switch tracing level without the need to restart application (such as in case of windows services)

Trace listener implementation would support an additional attribute namely refreshTraceConfig of type boolean to decide whether tracing needs to refresh the trace switch value.

  5. If there are any errors during the execution of custom trace listener, these should be logged to a text file separately.


Custom Database Trace Listener Implementation

Let’s understand how we have achieved the goals set forward for us by looking at the actual code. Find below the entire source code for the custom trace listener which uses a database table as its destination:

using System;
using System.Data;
using System.Data.SqlClient;
using System.Diagnostics;
using System.IO;
using System.Xml.Linq;
using System.Threading;
using System.Linq;

namespace AdvancedTracing
{
    // Delegate definition for the real method responsible for logging
    internal delegate void LogIt(string message, string type, string componentName);

    // Delegate for DBTraceFailed event 
    public delegate void DBTraceFailedHandler (string exceptionText);

    // IMPORTANT!!!IMPORTANT!!!IMPORTANT!!!IMPORTANT!!!
    // --------------------------------------------------
    // Dont write any debugging statements anywhere in this
    // class such as Debug.WriteLine or Trace.WriteLine
    // simply because it would go into an endless loop
    // --------------------------------------------------
    public class DBTraceListener : TraceListener
    {
        public event DBTraceFailedHandler DBTraceFailed;
 
        #region Constants

        private const string STORED_PROC_NAME = "prc_writetraceentry";
        private const string STORED_PROC_MESSAGE_PARAM_NAME = "@message";
        private const string STORED_PROC_MESSAGETYPE_PARAM_NAME = "@type";
        private const string STORED_PROC_COMPONENTNAME_PARAM_NAME = "@componentname";
        private const string TRACE_SWITCH_NAME = "DBTraceSwitch";
        private const string TRACE_SWITCH_DESCRIPTION = "Trace switch defined in config file for configuring trace output to database";

        // Not defining it as readonly string so that in future it could come
        // from an external source and we can provide initializer for it
        private static readonly string DEFAULT_TRACE_TYPE = "Verbose";

        #endregion

        #region Class Data

        // Database connection object
        private SqlConnection _cn;

        // Database command object
        private SqlCommand _cm;

        // Connection string for database
        private string _connectionString;

        // Flag for DBTraceListener object disposal status
        private bool _disposed = false;

        // Trace Switch object for controlling trace output, defaulting to Verbose
        private TraceSwitch TraceSwitch = new TraceSwitch(TRACE_SWITCH_NAME, TRACE_SWITCH_DESCRIPTION, DEFAULT_TRACE_TYPE);

        // Delegate to point to the method which would do actual operation of logging
        private LogIt workerMethod;

        // Component Name 
        private string _componentName;

        // Lock object
        private object _traceLockObject = new object();
        private object _fileLockObject = new object();

        // Timer to refresh trace configuration information
        private Timer _traceSwitchTimer;

        // Flag to indicate whether trace configuration data needs to be refreshed
        private bool _refreshTraceConfig = false;

        #endregion

        #region Properties

        public override bool IsThreadSafe
        {
            // TODO: We are logging to database and the core method responsible
            // for this places lock on the core code responsible for executing
            // database command to ensure that only one thread can access it at
            // a time. Considering this, we can really return true for this 
            // property but before doing that, just need to do some testing.
            get { return false; }
        }

        public string ConnectionString
        {
            get
            {
                if ( string.IsNullOrEmpty(this._connectionString))
                {
                    this.LoadAttributes();
                }
                return this._connectionString;
            }
            set { this._connectionString = value; }
        }

        public string ComponentName
        {
            get
            {
                if (string.IsNullOrEmpty(this._componentName))
                {
                    this.LoadAttributes();
                }
                return this._componentName;
            }
            set { this._componentName = value; }
        }

        /// 
        /// Setting this property to True would refresh Trace configuration
        /// data from system.diagnostics section in your application configuration
        /// file. It is important to note that it would only refresh trace configuration
        /// data and not entire configuration file. For example, while your application
        /// is running, if you change one of the appSettings values, it would not be 
        /// refreshed but changing trace switch value would be refreshed.
        /// 
        public bool RefreshTraceConfig 
        {
            get 
            {
                this.LoadAttributes();
                return this._refreshTraceConfig;
            }
            set
            {
                if (value)
                {
                    // Refresh trace section every 15 minutes
                    if (!this._refreshTraceConfig)
                    {
                        // i.e. If timer is not already active
                        this._refreshTraceConfig = true;
                        this._traceSwitchTimer = new Timer(new TimerCallback(RefreshSwitch), null, new TimeSpan(0, 15, 0), new TimeSpan(0, 15, 0));
                    }
                }
                else
                {
                    // If timer is active, stop it
                    this._refreshTraceConfig = false;
                    this._traceSwitchTimer.Dispose();
                    this._traceSwitchTimer = null;
                }
            }
        }

        #endregion

        #region Methods

        void RefreshSwitch(object o)
        {
            // Trace.Refresh call is not expected to throw any exception, but if it DOES
            // catch the exception and do nothing
            try
            {
                if (this.RefreshTraceConfig)
                {
                    Trace.Refresh();
                }
            }
            catch(Exception ex)
            {
                this.WriteLine(
                    string.Format("Trace.Refresh failed with following exception: {0}, ", ex.ToString()),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.Refresh failed with following exception: {0}, ", ex.ToString()));
            }
        }

        private void WriteEntryToInternalLog(string msg)
        {
            lock (this._fileLockObject)
            {
                try
                {
                    File.AppendAllText(AppDomain.CurrentDomain.BaseDirectory + @"\DBTraceListener.log",
                        string.Format("{0}{1}: {2}", Environment.NewLine, DateTime.Now.ToString(), msg));
                }
                catch
                {
                    // Do nothing
                }
            }
        }

        /// 
        /// Another method useful for testing if DBTraceListener is
        /// able to establish connection to database
        /// 
        /// void
        public bool TestDBConnection()
        {
            try
            {
                using (SqlConnection cn = new SqlConnection(this.ConnectionString))
                {
                    cn.Open();
                }
                return true;
            }
            catch
            {
                // In case of any exception just return false
                return false;
            }
        }

        internal bool ShouldLogTrace(TraceEventType eventType)
        {
            bool shouldLog = true;

            switch (eventType)
            {
                case TraceEventType.Critical:
                case TraceEventType.Error:
                    shouldLog = this.TraceSwitch.TraceError;
                    break;

                case TraceEventType.Warning:
                    shouldLog = this.TraceSwitch.TraceWarning;
                    break;

                case TraceEventType.Information:
                    shouldLog = this.TraceSwitch.TraceInfo;
                    break;

                case TraceEventType.Start:
                case TraceEventType.Stop:
                case TraceEventType.Suspend:
                case TraceEventType.Resume:
                case TraceEventType.Transfer:
                case TraceEventType.Verbose:
                    shouldLog = this.TraceSwitch.TraceVerbose;
                    break;
            }

            return shouldLog;
        }

        #region TraceEvent

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id)
        {
            this.TraceEvent(eventCache, source, eventType, id, string.Empty);
        }

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string message)
        {
            XElement msg;

            try
            {
                if (!this.ShouldLogTrace(eventType))
                    return;

                if (eventType == TraceEventType.Critical ||
                        eventType == TraceEventType.Error ||
                        eventType == TraceEventType.Warning)
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", message),
                                            new XElement("Id", id),
                                            new XElement("CallStack", eventCache.Callstack.ToString()),
                                            new XElement("ThreadId", eventCache.ThreadId),
                                            new XElement("ProcessId", eventCache.ProcessId)
                                       );
                }
                else
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", message));
                }

                this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
            }
            catch(Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed with following exception: {0}, for message {1} ", ex.ToString(), message),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed with following exception: {0}", ex.ToString()));
            }
        }

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string format, params object[] args)
        {
            XElement msg;

            try
            {
                if (!this.ShouldLogTrace(eventType))
                    return;

                if (eventType == TraceEventType.Critical ||
                        eventType == TraceEventType.Error ||
                        eventType == TraceEventType.Warning)
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", string.Format(format, args)),
                                            new XElement("Id", id),
                                            new XElement("CallStack", eventCache.Callstack.ToString()),
                                            new XElement("ThreadId", eventCache.ThreadId),
                                            new XElement("ProcessId", eventCache.ProcessId)
                                       );
                }
                else
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", string.Format(format, args)));
                }

                this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
            }
            catch (Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed with following exception: {0}, for message {1}", ex.ToString(), format),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed with following exception: {0}", ex.ToString()));
            }
        }

        #endregion

        #region TraceTransfer

        public override void TraceTransfer(TraceEventCache eventCache, string source, int id, string message, Guid relatedActivityId)
        {
            try
            {
                if (this.ShouldLogTrace(TraceEventType.Transfer))
                {
                    XElement msg = new XElement("TraceLog",
                            new XElement("Message", message),
                            new XElement("Source", source),
                            new XElement("Id", id),
                            new XElement("RelatedActivityId", relatedActivityId.ToString()),
                            new XElement("CallStack", eventCache.Callstack.ToString()),
                            new XElement("ThreadId", eventCache.ThreadId),
                            new XElement("ProcessId", eventCache.ProcessId));

                    this.WriteLine(msg.ToString(), TraceEventType.Verbose.ToString(), null);
                }
            }
            catch (Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceTransfer failed with following exception: {0}, for message {1} ", ex.ToString(), message),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceTransfer failed with following exception: {0}", ex.ToString()));
            }
        }

        #endregion

        public override string ToString()
        {
            return string.Format("DBTraceListener for Component: {0} using ConnectionString: {1}", this.ComponentName, this.ConnectionString);
        }

        #region Write Methods

        public override void Write(object o)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), null);
            }
        }

        public override void Write(string message)
        {
            this.WriteLine(message, null);
        }

        public override void Write(object o, string category)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), category);
            }
        }

        public override void Write(string message, string category)
        {
            this.WriteLine(message, category);
        }

        #endregion

        #region WriteLine Methods

        public override void WriteLine(object o)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), null);
            }
        }

        public override void WriteLine(object o, string category)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), category);
            }
        }

        public override void WriteLine(string message)
        {
            this.WriteLine(message, null);
        }

        override public void WriteLine(string message, string category)
        {
            try
            {
                if (!this.ShouldLogTrace(TraceEventType.Verbose))
                    return;

                // IMPORTANT!!!!
                // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
                XElement msg = new XElement("TraceLog",
                                   new XElement("Message", message));

                this.WriteLineInternal(msg.ToString(), category, null);
            }
            catch (Exception ex)
            {
                this.WriteEntryToInternalLog(string.Format("WriteLine failed with following exception: {0}", ex.ToString()));
            }
        }

        /// 
        /// This is a non-standard WriteLine method i.e. Trace class does not provide
        /// a WriteLine method taking three parameters. It is used by internal implementation
        /// of this class to provide functionality to log a different component name,
        /// **primarily aimed towards helping in debugging some particular scenario**
        /// 
        /// 
        /// 
        /// 
        public void WriteLine(string message, string category, string componentName)
        {
            try
            {
                if (!this.ShouldLogTrace(TraceEventType.Verbose))
                    return;

                // IMPORTANT!!!!
                // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
                XElement msg = new XElement("TraceLog",
                                   new XElement("Message", message));

                this.WriteLineInternal(msg.ToString(), category, componentName);
            }
            catch (Exception ex)
            {
                this.WriteEntryToInternalLog(string.Format("WriteLine failed with following exception: {0}", ex.ToString()));
            }
        }
        #endregion

        private void WriteLineInternal(string message, string category, string componentName)
        {
            // Perform the actual operation of logging **asynchronously**
            workerMethod = SaveLogEntry;
            workerMethod.BeginInvoke(message, category, componentName, null, null);
        }

        private void SaveLogEntry(string message, string category, string componentName)
        {
            // IMPORTANT!!!!
            // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
            lock (_traceLockObject)
            {
                try
                {
                    // save trace message to database
                    if (this._cn.State == ConnectionState.Broken ||
                        this._cn.State == ConnectionState.Closed)
                    {
                        this._cn.ConnectionString = this.ConnectionString;
                        this._cn.Open();
                    }

                    this._cm.Parameters[STORED_PROC_MESSAGE_PARAM_NAME].Value = message;
                    this._cm.Parameters[STORED_PROC_MESSAGETYPE_PARAM_NAME].Value = category;

                    if (string.IsNullOrEmpty(componentName))
                    {
                        // No value provided by caller. Look for the value defined 
                        // in application configuration file
                        if (string.IsNullOrEmpty(this.ComponentName))
                        {
                            this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = DBNull.Value;
                        }
                        else
                        {
                            this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = this.ComponentName;
                        }
                    }
                    else
                    {
                        // Specific value provided by caller for this specific trace/log
                        // Need to use the same
                        this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = componentName;
                    }
                    
                    this._cm.ExecuteNonQuery();
                }
                catch (Exception ex)
                {
                    // Raise event to let others know, just in case 
                    // someone interested
                    if (this.DBTraceFailed != null)
                    {
                        DBTraceFailed(ex.ToString());
                    }

                    // Write entry to internal log file
                    this.WriteEntryToInternalLog(ex.ToString());
                }
                finally
                {
                    // Nothing to dispose in case of exception
                }
            }
        }

        protected override string[] GetSupportedAttributes()
        {
            return new string[] { "connectionString", "componentName", "refreshTraceConfig" };
        }

        private void LoadAttributes()
        {
            if (Attributes.ContainsKey("connectionString"))
            {
                this.ConnectionString = this.Attributes["connectionString"];
            }

            if (Attributes.ContainsKey("componentName"))
            {
                this.ComponentName = this.Attributes["componentName"];
            }

            if (Attributes.ContainsKey("refreshTraceConfig"))
            {
                bool val;
                bool.TryParse(this.Attributes["refreshTraceConfig"], out val);
                this.RefreshTraceConfig = val;
            }
        }

        protected override void Dispose(bool disposing)
        {
            if (!this._disposed)
            {
                if (disposing)
                {
                    if (this._cn != null)
                        this._cn.Dispose();

                    if (this._cm != null)
                        this._cm.Dispose();

                    if (this._traceSwitchTimer != null)
                        this._traceSwitchTimer.Dispose();
                }

                this._disposed = true;
            }

            this._cm = null;
            this._cn = null;

            base.Dispose(disposing);
        }

        #endregion

        #region Constructors

        public DBTraceListener() : this(string.Empty) { }

        public DBTraceListener(string initializeData)
            : base(initializeData)
        {
            // Initialize connection object
            this._cn = new SqlConnection();
            this._cn.ConnectionString = initializeData;
            this.ConnectionString = initializeData;
            
            try
            {
                this._cn.Open();
            }
            catch(Exception ex)
            {
                // Write to internal 
                this.WriteEntryToInternalLog(string.Format("Could not connect to database from the provided connection string. Exception: {0}", ex.ToString()));

                // Let the caller know that this listener object cannot do its 
                // work because it cannot establish connection to database
                //
                // Since Tracing framework is initialized by CLR, you would 
                // in all likelihood get Could not create type... error
                throw;
            }

            // Setup command object
            this._cm = this._cn.CreateCommand();
            this._cm.CommandText = STORED_PROC_NAME;
            this._cm.CommandType = CommandType.StoredProcedure;
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGE_PARAM_NAME, DBNull.Value));
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGETYPE_PARAM_NAME, DBNull.Value));
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_COMPONENTNAME_PARAM_NAME, DBNull.Value));
        }
        #endregion
    }
}

The above piece of code is what you need for a custom database trace listener. You need to run additional database scripts to create the table and stored procedure required for this, the scripts for the same are as follows:

-- tracelog table
------------------------------------------------------------
if exists (select * from sys.tables where [name]='tracelog')
begin					
	print 'table tracelog already exists.'
end
else
begin
	print 'creating table tracelog...'

	create table [dbo].[tracelog](
		[traceid] [bigint] identity(1,1) not null,
		[message] [xml] null,
		[type] [varchar](20) null default ('Verbose'),
		[componentname] [varchar](200) null default (null),
		[loggeddate] [datetime] null default (getdate()),
	primary key clustered 
	(
		[traceid] asc
	)with (ignore_dup_key = off) on [primary]
	) on [primary]

	print 'table tracelog created.';
end	
go

-- stored procedure to write trace log entry
------------------------------------------------------------
if  exists (select * from sys.objects where object_id = object_id(N'[dbo].[prc_writetraceentry]') and type in (N'p', N'pc'))
	drop procedure [dbo].[prc_writetraceentry]
go

create proc prc_writetraceentry
	@message xml = null,
	@type varchar(100) = 'Verbose',
	@componentname varchar(200) = null
as
begin
	insert tracelog([message], type, componentname)
	values(@message, @type, @componentname)
end
go

-- add index to speed up data retrieval in case the table 
-- gets too big
------------------------------------------------------------
create nonclustered index [idx_tracelog_loggeddate] on [dbo].[tracelog] 
(
	[loggeddate] desc,
	[componentname] asc,
	[traceid] asc
)
go

Now, let’s modify the application configuration file and add the newly created trace listener. You need to add the trace listener as follows:

And execute the application and you would see the following in tracelog table in database:

In summary, salient features of custom db trace listener are as follows:

  1. Writes trace entries to database table as XML data

  2. Provides additional column to identify entries with the source application/component

  3. Writes to a text file the errors generated within DB trace listener implementation

In some future post (I don’t like to say next post as I might write about something completely different in my next post), we would try to look at advanced tracing techniques such as code injection to inject code into assembly which would log additional information at the start of each method execution so that you can trace each method as it executes in your application.

Happy Coding!!

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




About the author

Girish Jain works on Microsoft .Net framework technologies and is a big fan of WPF, WCF, and LINQ technologies. He is currently based in India with his wife and a daughter. When not spending time with family, Girish enjoys creating small tools, utilities, frameworks to improve developer productivity.

Sign In