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

ASP.NET 5 Logging using Trace Listeners and How-to Filter Log Entries

clock January 13, 2016 05:47 by author Girish Jain

Source code available at GitHub

Pluggable logging framework by ASP.NET 5...

ASP.NET 5 is the new open-source and cross-platform framework for building modern web applications using .NET. The new framework has in-built support for logging and it allows you to integrate with other logging frameworks too. You may need to write some code as a bridge between ASP.NET logging framework and your preferred logging provider by implementing interfaces provided by ASP.NET 5 such as ILoggingProvider and ILogger.

Can we plug trace listeners...?

In this post, I am going to cover how to use existing tracing framework in ASP.NET 5 projects. Tracing has been available in .NET since its inception. People have made investments into using trace listeners which write trace messages to a variety of destinations such as local file, database table, etc. They should be able to reuse their investment in ASP.NET 5 project as well. Let’s see how.

No more web.config...

Using tracing in in ASP.NET 4.x was fairly straight forward. You would define trace source and add trace listeners using web.config file. Something very simple as follows:

<system.diagnostics>
  <trace autoflush="true"></trace>
  <sources>
    <source name="MyServiceTraceSource" switchvalue="All">
      <listeners>
        <add name="MyServiceListener" type="System.Diagnostics.TextWriterTraceListener" initializedata="MyServiceLog.txt"></add>
      </listeners>
    </source>
  </sources>
</system.diagnostics>
And then in your code, you would write messages to trace source which would be received by the trace listener configured for trace source. That has changed with ASP.NET 5, as it does not use web.config file, we’ve lost that configuration-ability that we are so used to. Though, there’s nothing stopping us from defining trace listener configuration using new JSON config file and then using the same in code to create trace listeners that would listen for specific trace sources. For now, in this article, I am going to use trace listeners directly in code. 

Add tracing provider...

ASP.NET 5 has its own logging framework so we would need to plug trace listener provider to ASP.NET 5 logging framework. To use trace listeners in ASP.NET 5, you would need to add a NuGet package to your project called, Microsoft.Extensions.Logging.TraceSource. It has been developed by asp.net team as part of aspnet/Logging project. It lets you use TraceSource and TraceListener in your ASP.NET 5 project by using TraceSourceLogger class. 

You need to add Microsoft.Extensions.Logging.TraceSource package to your project as a dependency in project.json file as shown below:

"dependencies": {
    "Microsoft.AspNet.IISPlatformHandler": "1.0.0-rc1-final",
    "Microsoft.AspNet.Mvc": "6.0.0-rc1-final",
    "Microsoft.AspNet.Server.Kestrel": "1.0.0-rc1-final",
    "Microsoft.AspNet.StaticFiles": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.FileProviderExtensions": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.Json": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Console": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Debug": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.TraceSource": "1.0.0-rc1-final"
},

 

Add Trace Listener...

Next, you need to add a trace source listener to logger factory:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        new TextWriterTraceListener("AspNet5LoggingService.txt")
    );
    ...
}
    

Note: TextWriterTraceListener is not available in .Net Core but .Net Framework only so once you use it in your code, you may get compile error for the same. If you do, you would need to remove dnxcore50 target framework from your project by modifying project.json file i.e. remove highlighted line below:

    "frameworks": {
      "dnx451": { },
      "dnxcore50": { }
    },

 

Get Logger...

Lastly, you need to get logger instance in your classes by injecting a dependency to your class for logger instance. There is couple of options available for adding a dependency to class constructor for logger instance:

1. One option is to use ILoggerFactory type as a dependency and then manually creating a logger by calling CreateLogger method on factory instance and passing in a category name.

2. Another option is to use Logger<T> as a dependency in your constructor by specifying generic type parameter.

When using ILoggerFactory, you need to manually create a logger whereas with Logger<T> you could directly start using it for logging. For most situations, using Logger<T> would suffice but when you don’t know the generic type parameter to be used or if you would like to create a logger with a certain category name, you could use ILoggerFactory. Let’s look at an example using both approaches:

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        private readonly ILogger<ValuesController> logger;
        public ValuesController(ILogger<ValuesController> logger)
        {
            this.logger = logger;
        }
        ...
    }
OR
    [Route("api/values2")]
    public class ValuesController2 : Controller
    {
        private readonly ILogger logger;
        public ValuesController2(ILoggerFactory loggerFactory)
        {
            this.logger = loggerFactory.CreateLogger("AspNet5LoggingService");
        }
        ...
    }

 

Use Logger...

Voila! You are done and now you can start using this logger instance to write log entries.

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        private readonly ILogger logger;
        public ValuesController(ILogger logger)
        {
            this.logger = logger;
        }
        // GET: api/values
        [HttpGet]
        public IEnumerable Get()
        {
            logger.LogInformation("Processing GET request for values.");
            return new string[] { "value1", "value2" };
        }
    }

When executed, it would write log entry in trace destination by trace listener, which in my case was the log file specified with TextWriterTraceListener.

 

Noisy log entries...

You would find that log file is created in wwwroot folder and it contains all log entries. But as you would have noticed, the log file also contains all log entries which are generated by ASP.NET 5 framework. You would see something like this:

    
    Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 4 : Hosting starting
    Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 5 : Hosting started
    Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 GET http://localhost:50998/api/values
    Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 DEBUG http://localhost:50998/ text/html
    Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 1 : DEBUG requests are not supported
    Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 4 : The request path /api/values does not match a supported file type
    ...
    ...
    AspNet5LoggingService Information: 0 : Processing GET request for values.    

This behavior is by design. All logging providers will get all logging messages and it’s for individual provider to filter the "category" of messages they are interested in. Most likely, you wouldn’t want all those entries in log file along with log entries created by your service code and that brings us to next step.

 

How to filter for log entries...?

You can filter log entries by adding a filter to TraceListener, which is defined as a property on TraceListener base class. It’s of type TraceFilter:

public System.Diagnostics.TraceFilter Filter { get; set; }

 

If you lookup TraceFilter class definition, you would notice that it’s an abstract class. There are few default TraceFilter implementations available and you could use them or create your own filter very easily. All you would need to do is derive a class from TraceFilter and override ShouldTrace method. For this example, I am going to use existing SourceFilter class, which comes with .NET.

You could add a TraceFilter to your listener as follows:

    var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
    listener.Filter = new SourceFilter("AspNet5LoggingService");
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        listener
    );

 

Where are my filtered log entries...?

Depending upon your project and the number of log entries being generated, it may happen that you don’t see any new trace messages in your log file, especially after you filtered for trace messages generated by your service code. If you are using a TextWriterTraceListener, you may not see your log entries immediately in log file, though the log file would be created immediately (if it does not exist already). This is where I struggled and ended up spending quite some time debugging why I don't see log entries in my file, only to find out later about a feature with the specific listerner that I was using. This happens because TextWriterTraceListener writes data to the file stream and those trace messages are buffered. It does not flush the buffered data with each write. In previous versions of .NET, you would normally add following to your web.config file.

<trace autoflush="true" />

 

which would cause trace listeners to flush trace messages immediately. To achieve the same in ASP.NET 5, you can add following in code:

    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
    {
        loggerFactory.AddConsole(Configuration.GetSection("Logging"));
        loggerFactory.AddDebug();

        // This would prevent TextWriterTraceListener from buffering trace messages but cause
        // it to flush them as each trace message is sent to listener
        if (env.IsDevelopment())
        {
            Trace.AutoFlush = true;
        }        

        var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
        listener.Filter = new SourceFilter("AspNet5LoggingService");
        loggerFactory.AddTraceSource(
            new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
            listener
        );
        ...
    }

I am opting for AutoFlush behavior only in case of development environment because that's where we would need log entries to be reflected in file immediately whereas in production environment buffering log messages would give better performance. If you don’t set AutoFlush property, you would need to wait until buffered data in stream is written to file on disk.

Summary...

In this article we saw how to

1. Use trace listener in ASP.NET 5 project

2. Filter trace entries at the trace listener level

3. Use Trace.AutoFlush in code to prevent trace messages from being buffered in memory

NOTE: Please note that this article was written using ASP.NET 5 RC1 and by the time RTM comes out, which is expected in another couple of months, there may be some changes.

Happy Coding.

Vande Mataram!

(A salute to motherland)




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




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