Alois Kraus

blog

  Home  |   Contact  |   Syndication    |   Login
  109 Posts | 8 Stories | 296 Comments | 162 Trackbacks

News



Article Categories

Archives

Post Categories

Image Galleries

Programming

This time I wanted to write something about the .NET Framework that is solved not optimal of the .NET Framework. My unsuspecting victim is the well known System.Diagnostics.Trace class. Static classes have the big plus that they are easy to use but they can be very hard to maintain if you want to extend it (no derivation) and have a lifetime problem with the objects that are created inside it. The Trace facade is in my opinion a prominent example of  how you should not design a reliable static facade class. It's has many features that are nice but it's at the same time a fine example of design that has lost its vision. It tries to do too many things at the same time without succeeding in the optimal solution for all the goals it might have. Tracing should be fast, right? The .NET Trace definitely not the fastest solution. Yes it's flexible and can be very good configured inside your App.config file. But if you have used the Microsoft Logging Application Block of Enterprise Library 2.0 once then you know how much farther design for flexibility can be done. But I must admit that the Entlib TraceListeners does derive from the .NET ones. Below is a +- table about the .NET Trace regarding Performance Reliability and Extensibility.
In the following article I will show you what reliability issues there are and how to solve them.

Performance Reliability Extensibility/
Ease of use
TraceSwitches allow to configure at run  time what  should be traced.


- DefaultTraceListener  uses OutputDebugString  which  is by far the slowest method to trace.


 
- I loose traces if I do not call Trace.Close/Flush from time to time.

- Static Trace.Close is a mistake because I cannot really close something that is static.

- A Trace.Write after a Trace.Close causes loss of all following traces in case of file based listeners.

(+ Some Listeners do reopen itself after being closed. The File Listener can do this if you init it with a file name)
Dynamic Trace Switch Configuration

+ Dynamic Trace Listener Configuration

- Other (Logging) solutions are far more flexible.

- It is nearly impossible to write a program that does  capture all traces even during application shutdown.

The most obvious reliability problem I did find is demonstrated with a very simple Console Application:

    class Program

    {

        static void Main(string[] args)

        {

            Program pr = new Program(); // Create instance that will be finalized later

            TextWriterTraceListener listener = new TextWriterTraceListener(@"C:\trace.txt");

            Trace.Listeners.Clear();  // Remove default trace listener

            Trace.Listeners.Add(listener);

 

            Trace.WriteLine("First Trace");  // Generate some trace messages

            Trace.WriteLine("Perhaps last Trace.");

        }

    }


This small program does generate a 0 byte trace log file on my hard disk. Why? Because the StreamWriter is not flushed during Application exit. You can set the Trace.AutoFlush property to true for all trace listeners but you will loose about 30-50% throughput by doing this. Tracing should not alter application timing because if your (e.g. multithreading) timing dependant error goes away when you attach a debugger or enabling tracing you are left with the last option to insert printf statements inside your code and try it then again. For this reason we should strive for maximal speed and reliable delivery of our trace messages at the same time to make this worst case scenario happen less often..
Ok if I want performance then I will call Trace.Flush from time to time to ensure that my traces are written. During application exit I have to place the Trace.Close (Trace.Flush produces the same problem) at a strategic place to ensure that my traces are written.

    class Program

    {

        ~Program()

        {

           Trace.Close();  // ensure that all traces are flushed (Trace.Flush has the same effect that is shown below)

        }

 

        static void Main(string[] args)

        {

            Program pr = new Program(); // Create instance that will be finalized later

            TextWriterTraceListener listener = new TextWriterTraceListener(@"C:\trace.txt");

            Trace.Listeners.Add(listener);

 

            Trace.WriteLine("First Trace");  // Generate some trace messages

            Trace.WriteLine("Perhaps last Trace.");

        }

    }


Ok that does look better. We do now ensure that we flush the underlying  StreamWriter in our Finalizer. But wait Finalizers are not always called during application shutdown. We can remedy this situation by deriving from CriticalFinalizerObject. Due to our efforts to make it more reliable we are greeted with the following output:

Unhandled Exception: System.ObjectDisposedException: Cannot access a closed file.
   at System.IO.__Error.FileNotOpen()
   at System.IO.FileStream.Write(Byte[] array, Int32 offset, Int32 count)
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at System.IO.StreamWriter.Dispose(Boolean disposing)
   at System.IO.StreamWriter.Close()
   at System.Diagnostics.TextWriterTraceListener.Close()
   at System.Diagnostics.TraceInternal.Close()
   at System.Diagnostics.Trace.Close()
   at TraceTest.Program.Finalize()

Hey who did invite this exception to our party? To better understand whats going on we have to understand what does happen under the covers of the static Trace facade.
From the functional point of view our simple file trace is exactly the same as the following code snippet:

        static void Main(string[] args)

        {

            FileStream file = new FileStream(@"C:\Trace.txt", FileMode.Create);

            StreamWriter writer = new StreamWriter(file);

            writer.WriteLine("Our Trace Line");

        }

Do you see the problem here? Who does close the StreamWriter to flush its cache? If you run this program the result is a 0 byte Trace.txt with nothing inside it. This is exactly what we got when we configured the TextWriterTraceListener into the static Trace facade. Lets have a look into FileStream and StreamWriter.

StreamWriter Classes
As you can see from the class diagram a StreamWriter does hold a reference to the underlying file stream which in turn does encapsulate the real file handle via a safe handle. What is interesting in this picture that StreamWriter does NOT implement a finalizer whereas FileStream and SafeHandle do. This was decided by the CLR team as working model for streams to ensure that programmers close the darn StreamWriter before they exit or they will loose (consistently) data (= 0 byte Trace.txt). If StreamWriter did implement a finalizer it could work or not work depending on the order the finalizers are called. We can now imagine why the ObjectDisposedException was thrown.
Bad Case
Our problem here was that during AppDomain shutdown all finalizers are called in an arbitrary order. In our case we did try to flush our unsaved data while the FileStream was already finalized! If the CLR does change its GC implementation the following could also happen:

Good Case
We are left in the unfortunate situation that an exception can happen or not depending when we call (Trace.) Close. This is certainly a problem if we trace inside our finalizers and try to get the output away before our underlying file stream is finalized.

Static Facade Resource Management


The 10000$ question is if we can manage resources that are acquired by static facades.  If we do nothing about this we loose trace messages. The protocol for static facades should be the following:

  1. Acquire (static) Resources.
  2. Use static facade
  3. During application shutdown release resources as late as possible.
  4. After the resource release we ignore future calls to our static facade.

Sounds rather easy. And the truth it is easy to manage static resources. The new resource handling protocol for static facades goes like this

  1. Acquire Resources (FileStream, ...)
  2. Create your own static resource holder which does derive from CriticalFinalizerObject
  3. Prevent finalization of the acquired resources (GC.SuppressFinalize)
  4. Finalize the resources in our static resource holder in the order which is needed.

Thats really easy to do. Lets have a look at my brand new StaticResourceManager class:

    /// <summary>

    /// Ensures deterministic StreamWriter Flush, and File close at application exit for

    /// static facades. The cleanup is done after all normal finalizers have been called.

    /// </summary>

    public class StaticResourceManager : CriticalFinalizerObject

    {

        List<StreamWriter> writers = new List<StreamWriter>();

 

        public void AddStream(StreamWriter writer)

        {

            writers.Add(writer);

            FileStream fStream = GetIfFileStream(writer.BaseStream);

            if (fStream != null)

            {

                GC.SuppressFinalize(fStream); // prevent GC on FileStream

                // prevent file close at application exit before want to let it happen

                GC.SuppressFinalize(fStream.SafeFileHandle);

            }

        }

 

        static FileStream GetIfFileStream(Stream stream)

        {

            if (stream is FileStream)

                return (FileStream)stream;

            else

                return null;

        }

 

        /// <summary>

        /// Deterministic cleanup of StreamWriters

        /// 1. StreamWriter Close -> FileStream -> Close -> possible Writes

        /// 2. FileHandle Close

        /// </summary>

        ~StaticResourceManager()

        {

            foreach (StreamWriter writer in writers)

            {

                FileStream fstream = GetIfFileStream(writer.BaseStream);

                SafeFileHandle handle = null;

                if (fstream != null)

                {

                    handle = fstream.SafeFileHandle;

                }

                writer.Close();      // Close StreamWriter first

                if (handle != null// Close file handle now hurray

                    handle.Close();

            }

        }

    }


Now we can finally write a much more reliable TraceListener which does use it internally. To show you that it does really work you can try out my improved Trace Sample:

    class Program

    {

        // Our ResourceManager will ensure proper cleanup at application exit

        private static StaticResourceManager myResourceManager = new StaticResourceManager();

 

        Program()

        {

            FileStream file = new FileStream(@"C:\Trace.txt", FileMode.Create);

            StreamWriter writer = new StreamWriter(file);

            myResourceManager.AddStream(writer);  // ensure flush and close at Application exit

 

            // Use Tracing as usual

            TextWriterTraceListener listener = new TextWriterTraceListener(writer);

            Trace.Listeners.Add(listener);

 

            Trace.WriteLine("First Trace");  // Generate some trace messages

            Trace.WriteLine("Perhaps last Trace.");

        }

 

 

        ~Program()

        {

            Trace.WriteLine("Hello last Trace in finalizer.");

        }

 

        static void Main(string[] args)

        {

            Program p = new Program();

        }

    }


Finally we will see our beloved complete set of trace messages in our Trace.txt


Trace.txt
    First Trace
    Perhaps last Trace.
    Hello last Trace in finalizer.



Please note that this simple fix is still not the complete story since our listener should survive a Close call of the static Trace facade after all.



Conclusions

I have shown that some things do not work as expected by most developers when working with the static trace facade with true resource based Trace Listeners. A Close method in a static facade is a true crime which delegates the responsibility back to the users of the .NET Trace facility. But since Tracing can and should be used by virtually every .NET component that is written we cannot ensure anymore that another component has not called Trace.Close for any reason. Resource management should be handled by the facade itself properly. In fact it can be done quite easy and I have no idea why MS did not implement a solution which does ensure that all finalizers can use tracing with no risk of loosing messages. The trick is that all Critical Finalizers are called by the GC after all normal finalizers have been visited. Finally I do not understand why I am able to programatically remove a trace listener that has been added to the global Listener collection by perhaps a totally different component which does rely on it. I should only be able to remove elements that I have previously added by myself (could be done by a token that is returned by the add operation and must be supplied to the remove operation). That is all for the moment and I hope you did enjoy this little article and have gained a better understanding why you see a 0 byte file when using the .NET Trace right away. 

posted on Monday, June 12, 2006 9:11 PM

Feedback

# re: Why .NET Tracing is not reliable 10/4/2006 6:57 PM Marie
What I wonder is why everyone didn't immediately say "Doh! I am losing messages. This Trace thing isn't very useful." For example, if the program throws an exception and crashes and flush isn't called - so the last messages, pertaining to the crash are not received. None of my test examples worked properly with Trace, and given how long the functionality (or lack of it) has been around, why are there not more comments on this issue? Anyway, good article/blog. We found it useful.
marie (at) siliconcoach (dot) com

# re: Why .NET Tracing is not reliable 10/4/2006 7:09 PM Alois Kraus
Hi Marie,

good question. I think the answer is that most people use Visual Studio for debugging and only few actually add a thorough set of traces into their apps. Another thing is that the default Trace Listener writes to OutputDebugString which does (mostly) not cause message loss. You have to enable the FileTraceListener explicitly inside your App.config file or add it programmatically to the Trace Listener collection which obviously very few people did so far.

Yours,
Alois Kraus

# re: Why .NET Tracing is not reliable 10/22/2006 10:41 PM Brian
In defense of the CLR team, I believe they intended everyone to be using the Dispose-model and to be employing the 'using' statement within their Application entry point -- static void Main.

This does mean that the classes would have to implement IDisposable, but thats not hard at all. Since the Dispose method can be called multiple times it doesn't suffer from the race-conditions of the ~finalize code.

So, if Program implemented IDisposable, one could place Trace/Debug.Close() within it. Unexpected crashes of the system with no exception firing are an extreme case that I don't believe tracing would help you anyway, but if it was an exception that crashed your program it should be handled -- and your Trace closed.

From what I've read here, the problem seems to be with Finalizers, not necessarily .NET.

# re: Why .NET Tracing is not reliable 10/22/2006 11:35 PM Alois Kraus
Hi Brian,

the dispose/close call in main does work only if you do have only one thread in your system.
The finally block of your main is never called with this little program:

using System;
using System.Collections.Generic;
using System.Text;
using System.Threading;

namespace ExceptionInMultithreadedApp
{
class Program
{
static void Main(string[] args)
{
Console.WriteLine("In Console Main");
AppDomain.CurrentDomain.UnhandledException += new UnhandledExceptionEventHandler(CurrentDomain_UnhandledException);

try
{
new Thread( delegate()
{
Console.WriteLine("Multhreading Start");
throw new InvalidCastException("From nowhere to nowhere");
}).Start();
}
finally
{
Thread.Sleep(5000);
Console.WriteLine("We should see the message here?");
}

}

static void CurrentDomain_UnhandledException(object sender, UnhandledExceptionEventArgs e)
{
Console.WriteLine("Unhandled exception did happen in " + e.ExceptionObject);
}
}
}
You will get the following output:
In Console Main
Multhreading Start
Unhandled exception did happen in System.InvalidCastException: From nowhere to nowhere
at ExceptionInMultithreadedApp.Program.<Main>b__0() in C:\Source\ExceptionInMultithreadedApp\ExceptionInMultithreaded
App\Program.cs:line 20
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()
We should see the message here?

Unhandled Exception: System.InvalidCastException: From nowhere to nowhere
at ExceptionInMultithreadedApp.Program.<Main>b__0() in C:\Source\ExceptionInMultithreadedApp\ExceptionInMultithreaded
App\Program.cs:line 20
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()

Your program can bail out at any point without going back to main by simply calling Environment.Exit(), Environment.FailFast or throwing an exception in another thread. There is no simple "insert final Trace.Close inside here" place I do know of.
What is especially anoying is that for self created AppDomains there is no way to get notified of Unhandled Exceptions at all!

Yours,
Alois Kraus


# re: Why .NET Tracing is not reliable 4/14/2007 7:41 PM Sergei
I agree with Brian. IDisposable is a way to handle an issue and unexpected (unhandled) crashes are not a scenario to worry about.

I just wrote a windows service and I use .NET tracing. The goal for the service is to recover from even unexpected (recoverable) exceptions, thus every exception is handled and the exceptions that are not handled (out of memory) would be reported by windows.

# re: Why .NET Tracing is not reliable 9/20/2007 8:29 PM paatrice
Hello,

I had a similar problem when I try to write while between client and server.
I use this code
------------------------------
System.Net.WebClient Client = new System.Net.WebClient();
Client.UploadFile(baseLocation + fn, HIF.Value);
-------------------------------
Certains file works and others can't be upload. (message : System.ObjectDisposedException: Cannot access a closed file.)

I try to understand your code but it's too hard for me. Could you help me to modify my code and allow download all file .

Tanks you for your help.

Patrice

# re: Why .NET Tracing is not reliable 11/12/2007 4:09 AM Ayman Wassif
I fixed my problem by suppressing the Finalize on the base stream after I opened the file

Here is the Line I added after opening the file
GC.SuppressFinalize(myLogStream.BaseStream);

Thsn at the class distructor I could Flush and Close the file

# re: Why .NET Tracing is not reliable 7/3/2008 1:14 AM Advait Supnekar
Thanks for the step by step explanation

# re: Why .NET Tracing is not reliable 5/2/2011 9:15 AM David Boarman
nice...I needed a reason to rewrite my Logging utility.

# re: Why .NET Tracing is not reliable 8/16/2012 7:14 PM Jeroen

I'd rather dispose the classes i constructed over putting them in a 'dispose'bin.

class Program
{
TextWriterTraceListener _listener;

static void Main(string[] args)
{
Program pr = new Program(); // Create instance that will be finalized later
_listener = new TextWriterTraceListener(@"C:\trace.txt");
Trace.Listeners.Add(_listener);

Trace.WriteLine("First Trace"); // Generate some trace messages
Trace.WriteLine("Perhaps last Trace.");
}

~Program()
{
Trace.Flush(); // ensure that all traces are flushed
Trace.Listeners.Remove(_listener);
listener.Dispose();
}
}


# re: Why .NET Tracing is not reliable 8/16/2012 7:18 PM Jeroen
This is even better i guess.

class Program
{
static void Main(string[] args)
{
Program pr = new Program(); // Create instance that will be finalized later
using(TextWriterTraceListener listener = new TextWriterTraceListener(@"C:\trace.txt"))
{
Trace.Listeners.Add(_listener);

Trace.WriteLine("First Trace"); // Generate some trace messages
Trace.WriteLine("Perhaps last Trace.");

Run(); // Do something

Trace.Listeners.Remove(_listener);
}
}
}


Post A Comment
Title:
Name:
Email:
Comment:
Verification: