fix: improve Windows Event Log messages when logging fails

Zywave · Dec 15, 2016 · 56e8e61 · 56e8e61
1 parent 8c4afab
commit 56e8e61
Show file tree

Hide file tree

Showing 9 changed files with 265 additions and 75 deletions.
diff --git a/SMLogging-net35/SMLogging-net35.csproj b/SMLogging-net35/SMLogging-net35.csproj
@@ -136,6 +136,9 @@
     <Compile Include="..\SMLogging\TraceSourceConverter.cs">
       <Link>TraceSourceConverter.cs</Link>
     </Compile>
+    <Compile Include="..\SMLogging\WindowsEventLogTraceListener.cs">
+      <Link>WindowsEventLogTraceListener.cs</Link>
+    </Compile>
     <Compile Include="Properties\AssemblyInfo.cs" />
   </ItemGroup>
   <ItemGroup>

diff --git a/SMLogging.Lab.Client/App.config b/SMLogging.Lab.Client/App.config
@@ -6,14 +6,14 @@
   <system.serviceModel>
     <extensions>
       <behaviorExtensions>
-        <add name="requestLogging" type="SMLogging.RequestLoggingBehaviorExtension, SMLogging"/>
-        <add name="errorLogging" type="SMLogging.ErrorLoggingBehaviorExtension, SMLogging"/>
+        <!--<add name="requestLogging" type="SMLogging.RequestLoggingBehaviorExtension, SMLogging"/>-->
+        <!--<add name="errorLogging" type="SMLogging.ErrorLoggingBehaviorExtension, SMLogging"/>-->
       </behaviorExtensions>
     </extensions>
     <behaviors>
       <endpointBehaviors>
         <behavior>
-          <requestLogging />
+          <!--<requestLogging />-->
         </behavior>
       </endpointBehaviors>
     </behaviors>
@@ -82,13 +82,25 @@
       <source name="System.ServiceModel.RequestLogging" switchValue="Information">
         <listeners>
           <remove name="Default" />
-          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\requests.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" />
+          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\requests.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" failTraceSource="System.ServiceModel.RequestLogging.Fail"/>
         </listeners>
       </source>
-      <source name="System.ServiceModel.ErrorLogging" switchValue="Error">
+      <source name="System.ServiceModel.ErrorLogging" switchValue="Error" >
         <listeners>
           <remove name="Default" />
-          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\errors.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" />
+          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\errors.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" failTraceSource="System.ServiceModel.ErrorLogging.Fail"/>
+        </listeners>
+      </source>
+      <source name="System.ServiceModel.ErrorLogging.Fail" switchValue="Error">
+        <listeners>
+          <remove name="Default" />
+          <add name="EventLog" type="SMLogging.WindowsEventLogTraceListener" initializeData="SMLogging" />
+        </listeners>
+      </source>
+      <source name="System.ServiceModel.RequestLogging.Fail" switchValue="Error">
+        <listeners>
+          <remove name="Default" />
+          <add name="EventLog" type="SMLogging.WindowsEventLogTraceListener, SMLogging" initializeData="SMLogging" />
         </listeners>
       </source>
     </sources>

diff --git a/SMLogging.Lab/Web.config b/SMLogging.Lab/Web.config
@@ -11,8 +11,8 @@
   <system.serviceModel>
     <extensions>
       <behaviorExtensions>
-        <add name="requestLogging" type="SMLogging.RequestLoggingBehaviorExtension, SMLogging"/>
-        <add name="errorLogging" type="SMLogging.ErrorLoggingBehaviorExtension, SMLogging"/>
+        <!--<add name="requestLogging" type="SMLogging.RequestLoggingBehaviorExtension, SMLogging"/>
+        <add name="errorLogging" type="SMLogging.ErrorLoggingBehaviorExtension, SMLogging"/>-->
       </behaviorExtensions>
     </extensions>
     <behaviors>
@@ -22,8 +22,8 @@
           <serviceMetadata httpGetEnabled="true" httpsGetEnabled="true"/>
           <!-- To receive exception details in faults for debugging purposes, set the value below to true.  Set to false before deployment to avoid disclosing exception information -->
           <serviceDebug includeExceptionDetailInFaults="true"/>
-          <requestLogging />
-          <errorLogging />
+          <!--<requestLogging />
+          <errorLogging />-->
         </behavior>
       </serviceBehaviors>
     </behaviors>
@@ -104,18 +104,30 @@
   </system.webServer>
 
   <system.diagnostics>
-    <!--<trace autoflush="true"/>-->
+    <trace autoflush="true"/>
     <sources>
       <source name="System.ServiceModel.RequestLogging" switchValue="Information">
         <listeners>
           <remove name="Default" />
-          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\requests.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" />
+          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\requests.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" failTraceSource="System.ServiceModel.RequestLogging.Fail"/>
         </listeners>
       </source>
       <source name="System.ServiceModel.ErrorLogging" switchValue="Error" >
         <listeners>
           <remove name="Default" />
-          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\errors.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" />
+          <add name="File" type="SMLogging.BackgroundFileTraceListener, SMLogging" initializeData="%SystemDrive%\servicemodel\logs\{AppName}\errors.{DateTime:yyMMdd}.log" rollingMode="DateTime" rollingInterval="Day" failTraceSource="System.ServiceModel.ErrorLogging.Fail"/>
+        </listeners>
+      </source>
+      <source name="System.ServiceModel.ErrorLogging.Fail" switchValue="Error">
+        <listeners>
+          <remove name="Default" />
+          <add name="EventLog" type="SMLogging.WindowsEventLogTraceListener" initializeData="SMLogging" />
+        </listeners>
+      </source>
+      <source name="System.ServiceModel.RequestLogging.Fail" switchValue="Error">
+        <listeners>
+          <remove name="Default" />
+          <add name="EventLog" type="SMLogging.WindowsEventLogTraceListener, SMLogging" initializeData="SMLogging" />
         </listeners>
       </source>
     </sources>

diff --git a/SMLogging.Setup.CustomActions/CustomActions.cs b/SMLogging.Setup.CustomActions/CustomActions.cs
@@ -349,7 +349,7 @@ private static void SetupDirectory(string path)
         private const string ErrorLoggingFailSourceName = "System.ServiceModel.ErrorLogging.Fail";
         private const string ErrorLoggingFailSourceSwitchValue = "Error";
         private const string EventLogListenerName = "EventLog";
-        private const string EventLogTraceListenerType = "System.Diagnostics.EventLogTraceListener";
+        private const string EventLogTraceListenerType = "SMLogging.WindowsEventLogTraceListener, SMLogging, Version={0}.0, Culture=neutral, PublicKeyToken=ddc81ec55fc35caf";
         private const string EventLogSourceName = "SMLogging";
 
         #endregion

diff --git a/SMLogging/BackgroundFileTraceListener.cs b/SMLogging/BackgroundFileTraceListener.cs
@@ -204,8 +204,8 @@ private void EnqueueEvent(Event evt, bool force)
                 if (force)
                 {
                     Event oldEvt;
-                    _queue.TryDequeue(out oldEvt);
                     _queue.Enqueue(evt);
+                    _queue.TryDequeue(out oldEvt);
                 }
 
                 if (!_maxQueueSizeReached)

diff --git a/SMLogging/FileTraceListener.cs b/SMLogging/FileTraceListener.cs
@@ -512,9 +512,9 @@ private string FormatFilePath(string path)
             }
             namedArgs["DateTime"] = dateTime;
             namedArgs["Timestamp"] = DateTime.UtcNow.Ticks;
-            namedArgs["ProcessId"] = _processId;
-            namedArgs["ProcessName"] = RemoveInvalidFileNameCharacters(_processName);
-            namedArgs["AppName"] = RemoveInvalidFileNameCharacters(_appName);
+            namedArgs["ProcessId"] = ProcessId;
+            namedArgs["ProcessName"] = RemoveInvalidFileNameCharacters(ProcessName);
+            namedArgs["AppName"] = RemoveInvalidFileNameCharacters(AppName);
 
             return StringHelpers.NamedFormat(CultureInfo.InvariantCulture, path, namedArgs);
         }
@@ -667,22 +667,7 @@ private static string RemoveInvalidFileNameCharacters(string value)
         private FileLockHandlerBase _lockHandler;
         private FileLockStream _lockStream;
         private TextWriter _writer;
-
-        private static readonly int _processId;
-        private static readonly string _processName;
-        private static readonly string _appName;
-
-        static FileTraceListener()
-        {
-            using (var process = Process.GetCurrentProcess())
-            {
-                _processId = process.Id;
-                _processName = process.ProcessName;
-            }
-
-            _appName = AppDomain.CurrentDomain.GetFriendlyName();
-        }
-
+
         #endregion
     }
 }
diff --git a/SMLogging/SMLogging.csproj b/SMLogging/SMLogging.csproj
@@ -55,6 +55,7 @@
     <Compile Include="EncodingConverter.cs" />
     <Compile Include="ErrorLoggingBehavior.cs" />
     <Compile Include="ErrorLoggingErrorHandler.cs" />
+    <Compile Include="WindowsEventLogTraceListener.cs" />
     <Compile Include="ExclusiveFileLockHandler.cs" />
     <Compile Include="FileLockHandlerBase.cs" />
     <Compile Include="FileLockingMode.cs" />

diff --git a/SMLogging/TraceListenerBase.cs b/SMLogging/TraceListenerBase.cs
@@ -80,6 +80,21 @@ protected TraceListenerBase(string name)
 
         #endregion
 
+        /// <summary>
+        /// Gets the process identifier.
+        /// </summary>
+        protected int ProcessId => _processId;
+
+        /// <summary>
+        /// Gets the name of the process.
+        /// </summary>
+        protected string ProcessName => _processName;
+
+        /// <summary>
+        /// Gets the name of the application.
+        /// </summary>
+        protected string AppName => _appName;
+
         #region Public Methods
 
         /// <summary>
@@ -97,7 +112,7 @@ public override void TraceData(TraceEventCache eventCache, string source, TraceE
 
             if (ShouldTrace(eventCache, source, eventType, id, null, null, data, null))
             {
-                var message = String.Empty;
+                var message = string.Empty;
                 if (data != null)
                 {
                     message = data.ToString();
@@ -150,7 +165,7 @@ public override void TraceData(TraceEventCache eventCache, string source, TraceE
         [ComVisible(false)]
         public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id)
         {
-            TraceEvent(eventCache, source, eventType, id, String.Empty);
+            TraceEvent(eventCache, source, eventType, id, string.Empty);
         }
 
         /// <summary>
@@ -188,10 +203,10 @@ public override void TraceEvent(TraceEventCache eventCache, string source, Trace
 
             if (ShouldTrace(eventCache, source, eventType, id, format, args))
             {
-                var message = String.Empty;
+                var message = string.Empty;
                 if (args != null)
                 {
-                    message = String.Format(CultureInfo.InvariantCulture, format, args);
+                    message = string.Format(CultureInfo.InvariantCulture, format, args);
                 }
                 else
                 {
@@ -213,37 +228,7 @@ public virtual void WriteTrace(TraceEventCache eventCache, string source, TraceE
         {
             WriteLine(FormatTrace(eventCache, source, eventType, id, message));
 
-            var includeOptions = ((int)TraceOutputOptionsLevels & (int)eventType) != 0;
-            if (includeOptions && eventCache != null)
-            {
-                IndentLevel++;
-                if ((TraceOptions.ProcessId & TraceOutputOptions) != TraceOptions.None)
-                {
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.ProcessIdTraceToken, eventCache.ProcessId));
-                }
-                if ((TraceOptions.LogicalOperationStack & TraceOutputOptions) != TraceOptions.None)
-                {
-                    var stack = StringHelpers.Join(", ", eventCache.LogicalOperationStack.ToArray());
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.LogicalOperationStackTraceToken, stack));
-                }
-                if ((TraceOptions.ThreadId & TraceOutputOptions) != TraceOptions.None)
-                {
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.ThreadIdTraceToken, eventCache.ThreadId));
-                }
-                if ((TraceOptions.DateTime & TraceOutputOptions) != TraceOptions.None)
-                {
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.DateTimeTraceToken, eventCache.DateTime));
-                }
-                if ((TraceOptions.Timestamp & TraceOutputOptions) != TraceOptions.None)
-                {
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.TimestampTraceToken, eventCache.Timestamp));
-                }
-                if ((TraceOptions.Callstack & TraceOutputOptions) != TraceOptions.None)
-                {
-                    WriteLine(String.Format(CultureInfo.InvariantCulture, AssemblyResources.CallstackTraceToken, eventCache.Callstack));
-                }
-                IndentLevel--;
-            }
+            WriteTraceOutput(eventCache, eventType);
         }
 
         /// <summary>
@@ -308,13 +293,15 @@ protected virtual string FormatTrace(TraceEventCache eventCache, string source,
             namedArgs["EventType"] = eventType.ToString();
             namedArgs["EventId"] = id;
             namedArgs["Message"] = message;
-            namedArgs["ProcessId"] = eventCache != null ? eventCache.ProcessId : 0;
-            namedArgs["ThreadId"] = eventCache != null ? eventCache.ThreadId : String.Empty;
+            namedArgs["ProcessId"] = ProcessId;
+            namedArgs["ProcessName"] = ProcessName;
+            namedArgs["AppName"] = AppName;
+            namedArgs["ThreadId"] = eventCache != null ? eventCache.ThreadId : string.Empty;
             namedArgs["ActivityId"] = Trace.CorrelationManager.ActivityId;
-            namedArgs["LogicalOperationStack"] = String.Join(", ", Trace.CorrelationManager.LogicalOperationStack.ToArray().Select(s => s.ToString()).ToArray());
+            namedArgs["LogicalOperationStack"] = string.Join(", ", Trace.CorrelationManager.LogicalOperationStack.ToArray().Select(s => s.ToString()).ToArray());
             namedArgs["NewLine"] = Environment.NewLine;
 
-            var result = String.Empty;
+            var result = string.Empty;
 
             try
             {
@@ -328,6 +315,52 @@ protected virtual string FormatTrace(TraceEventCache eventCache, string source,
             return result;
         }
 
+        /// <summary>
+        /// Writes the trace output.
+        /// </summary>
+        /// <param name="eventCache">The event cache.</param>
+        /// <param name="eventType">Type of the event.</param>
+        /// <param name="writeLine">The write line method. Default is <see cref="M:WriteLine"/>.</param>
+        protected virtual void WriteTraceOutput(TraceEventCache eventCache, TraceEventType eventType, Action<string> writeLine = null)
+        {
+            if (writeLine == null)
+            {
+                writeLine = WriteLine;
+            }
+
+            var includeOptions = ((int)TraceOutputOptionsLevels & (int)eventType) != 0;
+            if (includeOptions && eventCache != null)
+            {
+                IndentLevel++;
+                if ((TraceOptions.ProcessId & TraceOutputOptions) != TraceOptions.None)
+                {
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.ProcessIdTraceToken, eventCache.ProcessId));
+                }
+                if ((TraceOptions.LogicalOperationStack & TraceOutputOptions) != TraceOptions.None)
+                {
+                    var stack = StringHelpers.Join(", ", eventCache.LogicalOperationStack.ToArray());
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.LogicalOperationStackTraceToken, stack));
+                }
+                if ((TraceOptions.ThreadId & TraceOutputOptions) != TraceOptions.None)
+                {
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.ThreadIdTraceToken, eventCache.ThreadId));
+                }
+                if ((TraceOptions.DateTime & TraceOutputOptions) != TraceOptions.None)
+                {
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.DateTimeTraceToken, eventCache.DateTime));
+                }
+                if ((TraceOptions.Timestamp & TraceOutputOptions) != TraceOptions.None)
+                {
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.TimestampTraceToken, eventCache.Timestamp));
+                }
+                if ((TraceOptions.Callstack & TraceOutputOptions) != TraceOptions.None)
+                {
+                    writeLine(string.Format(CultureInfo.InvariantCulture, AssemblyResources.CallstackTraceToken, eventCache.Callstack));
+                }
+                IndentLevel--;
+            }
+        }
+
         /// <summary>
         /// Determines if the trace listener should emit a trace statement based on the trace information provided.
         /// </summary>
@@ -453,7 +486,7 @@ protected void ApplyConfiguration()
                     {
                         if (isRequired)
                         {
-                            throw new ConfigurationErrorsException(String.Format(CultureInfo.InvariantCulture, AssemblyResources.MissingRequiredAttribute, name));
+                            throw new ConfigurationErrorsException(string.Format(CultureInfo.InvariantCulture, AssemblyResources.MissingRequiredAttribute, name));
                         }
                         else if (!defaultValue.Equals(nullValue))
                         {
@@ -488,7 +521,22 @@ protected void ApplyConfiguration()
 
         private bool _hasConfiguration = false;
         private bool _isInitialized = false;
-        private readonly object _initializeLock = new object(); 
+        private readonly object _initializeLock = new object();
+
+        private static readonly int _processId;
+        private static readonly string _processName;
+        private static readonly string _appName;
+
+        static TraceListenerBase()
+        {
+            using (var process = Process.GetCurrentProcess())
+            {
+                _processId = process.Id;
+                _processName = process.ProcessName;
+            }
+
+            _appName = AppDomain.CurrentDomain.GetFriendlyName();
+        }
 
         private const string _defaultTraceFormat = "{DateTime:yyyy-MM-dd} {DateTime:HH:mm:ss.FFF} {Message}";
         private const string _defaultTraceDataDelimiter = " ";