C# garbage collector seems to be closing my StreamWriter too early

Question

I have a logger class thats a singleton. In it's destructor I call Close() which prints the footer for the log and then closes the StreamWriter.

 public void Close()
    {
        WriteLogFileFooter();

        _logFile.Flush();

        _logFile.Close();
    }

The problem is when System.Enviornment.Exit(1) is called from elsewhere in the program (portions that I didn't write myself), the footer is never printed and my logger throws an exception for trying to write to a closed stream. I can only assume the Exit command is causing my StreamWriter to be closed before my Singleton is destructed. I tried to use GC.SupressFinalize() on my StreamWriter but that didn't seem to help.

Answer 1

You are violating one explicit rule for finalizers:

The Finalize method should not reference any other objects.

http://msdn.microsoft.com/en-us/library/b1yfkh5e(v=VS.90).aspx

It's entirely possible that the managed object you hold a reference to is collected before your object is collected when the application exits.

UPDATE

If you need to clean up managed resources when the application exits, you could hook up the ProcessExit event of AppDomain rather than rely on non-deterministic behavior of finalizer execution.

.NET Console Application Exit Event

Answer 2

You should make your logger implement IDisposable, and use it in a using block. This means that it will be deterministically disposed, whereas now it is being nondeterministically destructed.

The cause of the error is that your stream will sometimes be closed before the logger, as Exit basically destroys everything (nondeterministically) and quits. You should use a deterministic pattern (IDisposable) to avoid this.

In reality, destructors are rarely useful in C#, for the precise reason that they are non-deterministic. They only are worth using for releasing unmanaged resources.

Also, implementing IDisposable may make it inconvenient to use a singleton. I personally think it's better to create an instance to be used throughout the program and disposed at the end, rather than an explicit singleton.

Answer 3

As others have already clearly stated, you should not attempt to access your _logFile object at all from your logger class' finalizer. You shouldn't access any other objects in a finalizer, because the Garbage Collector might already have wiped them out of existence.

I think you could avoid your problem by a few simple steps:

1. Get rid of your current finalizer.

2. Perform a _logFile.Flush after every single write, instead of waiting until the very end of your logger object's lifetime when it might already be too late.

   Flushing a log file stream frequently seems legitimate to me because the whole point of having a log is using it to find, and deal with, situations where errors have occurred. If your process is suddenly terminated by an exceptional situation, your log should still be as complete as possible; thus flushing the log stream buffer frequently seems a sensible thing to do.

3. Make your logger implement IDisposable (this MSDN Magazine article will explain to you how this is done) and close your log file stream from there.

Answer 4

I had the same problems and my solution was as follows:

1. When creating the FileStream in the constructor of your class used GC.SuppressFinalize immediately. This makes you responsible for cleaning the stream
   
2. Close the stream in the Dispose() of the class

public class LogFileEventListener : IDisposable
{
    private bool disposed = false;
    private FileStream fileStream;

    public LogFileEventListener(string path)
    {
        //Opens a new file stream to log file
        this.fileStream = new FileStream(path, FileMode.Append, FileAccess.Write);
        GC.SuppressFinalize(this.fileStream);
    }

    /// <summary>Finalize the listener</summary>
    ~LogFileEventListener() { this.Dispose(); }

    /// <summary>Disposes the listener</summary>
    public override void Dispose()
    {
        try
        {
            if (!this.disposed)
            {
                /* Do you stuff */

                //Close the log file
                if (this.fileStream != null)
                {
                    this.fileStream.Close();
                    this.fileStream = null;
                }

                base.Dispose();
            }
        }
        finally
        {
            this.disposed = true;
            GC.SuppressFinalize(this);
        }
    }
}

Answer 5

Most likely the StreamWriter is being closed else where. Try creating an additional StreamWriter in your singleton's constructor, write to it a few times (to confirm that it is working), then write to it again in the destructor before calling close (close will also flush).

If the above works then you will know some other code is closing your log. If it does not work then you will know that it is a .NET thing (possibly having something to do with how/where the variable is referenced).

According to the documentation, you should be able to work around the issue by putting the StreamWriter in a base class. This of course will not work for you because your test case is not a standard finalization, but is a program exit, meaning .NET does what it wants when it wants. Instead, you should catch the exit event, dispose of this class, then return, to guarantee that things are disposed in the correct order. You should also check if the StreamWriter is already closed in the finalizer in case the program aborts due to an error.