Monday 28 November 2011

AppFabric Event Logger Thread Safe


On a recent project I used the new AppFabric Event Logger. One of the beauties of this logger is that it is a non-blocking call which means that for your application the logging of messages does not slow you down. You can continue your processing without concerns of IO Deadlocks etc. This is great for multithreading applications/environments. If you want a logger that can handle multithreading then this is the best option to use.

What happens in the background is that the logged message is put into a memory queue. Then the AppFabric Event Collection Service (viewable in services.msc) polls this queue every 15 seconds. Using the SQLBulkCopy IBulkCopy Interface the queued messages are bulk copied to the SQL database.

This is a far more efficient logging process as only one thread is in control of the logging. You can create your own SQLBulkCopy class that implement IBulkCopy which I will blog in another post

Note: AppFabric Logging is installed at C:\Windows\System32\AppFabric

Now in my case I had threads being created from my wcf service. I wanted to keep the same correlation ID across each thread. Sadly to say by default the AppFabric logger creates a different Correlation Id for each thread.  So essentially I wanted for each call one Correlation ID by the single service call, across multiple threads. To do this I passed a GUID between different threads. Look at the code below I set the System.Diagnostics.Eventing.EventProvider.SetActivityId and System.Diagnostics.Trace.CorrelationManager.ActivityId

This forces the AppFabric logger to use that GUID. Note you will need to call this only once on initial thread creation.

        /// <summary>
        /// Activity ID for the thread of the trace
        /// </summary>
        public string ActivityID
        {
            get { return innerGUID; }

            set {
                innerGUID = value;
                guidInner = Guid.Parse(innerGUID);
                System.Diagnostics.Eventing.EventProvider.SetActivityId(ref guidInner);
                System.Diagnostics.Trace.CorrelationManager.ActivityId = guidInner;

                this.WriteInformation("[AppFabricLogger].Guid", guidInner.ToString());
            }
        }

I include the complete thread safe source code for your reviewing and usage.


    /// <summary>
    /// WCF helper static class for custom logging to the AppFabric event
    /// </summary>
    public class AppFabricLogger
    {
        #region Constants Declaration       
        const string DIAGNOSTICS_CONFIG_SECTION_NAME = "system.serviceModel/diagnostics";

        const int ERROR_EVENT_ID = 301;
        const int WARNING_EVENT_ID = 302;
        const int INFO_EVENT_ID = 303;

        const int VERSION = 0;
        const int TASK = 0;
        const int OPCODE = 0;
        const long KEYWORDS = (long)0x20000000001e0004;
        const byte CHANNEL = 0x12;

        const int ERROR_LEVEL = 0x2;
        const int WARNING_LEVEL = 0x3;
        const int INFO_LEVEL = 0x4;
        #endregion Constants Declaration

        #region Event Descriptor Declaration
        private EventDescriptor errorDescriptor;
        private EventDescriptor warningDescriptor;
        private EventDescriptor infoDescriptor;
        #endregion Event Descriptor Declaration

        #region Others Declaration       
        private bool hostReferenceIsComplete;
        private string hostReference;
        private EventProvider innerEventProvider;
        private string innerGUID;
        private Guid guidInner;

        #endregion Others Declaration

        #region Host Reference Stuff
        private String HostReference
        {
            get
            {
                if (hostReferenceIsComplete == false)
                {
                    CreateHostReference();
                }
                return hostReference;
            }
        }

        private void CreateHostReference()
        {
            if (OperationContext.Current != null)
            {
                ServiceHostBase serviceHostBase = OperationContext.Current.Host;

                VirtualPathExtension virtualPathExtension = serviceHostBase.Extensions.Find<VirtualPathExtension>();
                if (virtualPathExtension != null && virtualPathExtension.VirtualPath != null)
                {

                    //     HostReference Format
                    //     <SiteName><ApplicationVirtualPath>|<ServiceVirtualPath>|<ServiceName>

                    string serviceName = serviceHostBase.Description.Name;
                    string applicationVirtualPath = HostingEnvironment.ApplicationVirtualPath;
                    string serviceVirtualPath = virtualPathExtension.VirtualPath.Replace("~", string.Empty);

                    hostReference = string.Format("{0}{1}|{2}|{3}", HostingEnvironment.SiteName, applicationVirtualPath, serviceVirtualPath, serviceName);

                    hostReferenceIsComplete = true;
                    return;
                }
            }

            // If the entire host reference is not available, fall back to site name and app virtual path.  This will happen
            // if you try to emit a trace from outside an operation (e.g. startup) before an in operation trace has been emitted.
            hostReference = string.Format("{0}{1}", HostingEnvironment.SiteName, HostingEnvironment.ApplicationVirtualPath);
        }
        #endregion Host Reference Stuff

        #region Constructor
        /// <summary>
        /// Constructor of the AppFabricLogger class
        /// </summary>
        public AppFabricLogger()
        {
            Guid providerId;
            DiagnosticSection config;

            // check whether the current app is being hosted
            if (HostingEnvironment.IsHosted)
            {
                // Hosted in web app
                config = (DiagnosticSection)WebConfigurationManager.GetSection(DIAGNOSTICS_CONFIG_SECTION_NAME);
                providerId = new Guid(config.EtwProviderId);
                Debug.WriteLine("PROVIDER::" + config);
                hostReferenceIsComplete = false;
            }
            else
            {
                // non web app
                config = (DiagnosticSection)ConfigurationManager.GetSection(DIAGNOSTICS_CONFIG_SECTION_NAME);               
                providerId = new Guid(config.EtwProviderId);
                hostReference = string.Empty;
                hostReferenceIsComplete = true;
                Debug.WriteLine("PROVIDER::" + config);
            }

            innerEventProvider = new EventProvider(providerId);

            errorDescriptor = new EventDescriptor(ERROR_EVENT_ID, VERSION, CHANNEL, ERROR_LEVEL, OPCODE, TASK, KEYWORDS);
            warningDescriptor = new EventDescriptor(WARNING_EVENT_ID, VERSION, CHANNEL, WARNING_LEVEL, OPCODE, TASK, KEYWORDS);
            infoDescriptor = new EventDescriptor(INFO_EVENT_ID, VERSION, CHANNEL, INFO_LEVEL, OPCODE, TASK, KEYWORDS);
        }
        #endregion Constructor

        #region Public Properties   
        /// <summary>
        /// Activity ID for the thread of the trace
        /// </summary>
        public string ActivityID
        {
            get { return innerGUID; }

            set {
                innerGUID = value;
                guidInner = Guid.Parse(innerGUID);
                System.Diagnostics.Eventing.EventProvider.SetActivityId(ref guidInner);
                System.Diagnostics.Trace.CorrelationManager.ActivityId = guidInner;

                this.WriteInformation("[AppFabricLogger].Guid", guidInner.ToString());
            }
        }
        #endregion Public Properties

        #region Logging the event

        /// <summary>
        /// Write the error event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="format">A composite format string</param>
        /// <param name="args">An array of objects that contain the event data to write.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteError(string name, string format, params object[] args)
        {
            return WriteError(name, string.Format(format, args));
        }

        /// <summary>
        /// Write the error event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="payload">The string to write as the event data.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteError(string name, string payload)
        {
            if (!innerEventProvider.IsEnabled(errorDescriptor.Level, errorDescriptor.Keywords))
            {
                return true;
            }
            return innerEventProvider.WriteEvent(ref errorDescriptor, name, HostReference, payload);
        }

        /// <summary>
        /// Write the warning event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="format">A composite format string</param>
        /// <param name="args">An array of objects that contain the event data to write.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteWarning(string name, string format, params object[] args)
        {
            return WriteWarning(name, string.Format(format, args));
        }

        /// <summary>
        /// Write the warning event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="payload">The string to write as the event data.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteWarning(string name, string payload)
        {
            if (!innerEventProvider.IsEnabled(warningDescriptor.Level, warningDescriptor.Keywords))
            {
                return true;
            }
            return innerEventProvider.WriteEvent(ref warningDescriptor, name, HostReference, payload);
        }

        /// <summary>
        /// Write the information event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="format">A composite format string</param>
        /// <param name="args">An array of objects that contain the event data to write.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteInformation(string name, string format, params object[] args)
        {
            //var tr = Trace.CorrelationManager.ActivityId;

            return WriteInformation(name, string.Format(format, args));
        }

        /// <summary>
        /// Write the information event
        /// </summary>
        /// <param name="name">Name of the event</param>
        /// <param name="payload">The string to write as the event data.</param>
        /// <returns>Boolean whether the event is written</returns>
        public bool WriteInformation(string name, string payload)
        {
            if (!innerEventProvider.IsEnabled(infoDescriptor.Level, infoDescriptor.Keywords))
            {
                return true;
            }
            return innerEventProvider.WriteEvent(ref infoDescriptor, name, HostReference, payload);
        }
        #endregion Logging the event
      
    }

No comments:

Post a Comment