c# thread safe logging issue not using singleton

Question

I'm creating a logging class in C# and I need it to be thread safe. I've implemented TextWriter.Synchronized and locks but I'm getting a very strange issue with the locks where they seem to not work.

I don't want to use a singleton or a static class because I want to be able to have multiple instances of this logging class at any given time and I want to synchronize the threads based on the log's filename. So if I have 30 threads with 3 different instances of the Log class all using the same log file, it will synchronize properly and not have any issues. Below is what I've come up with so far. I've left out some of the code that is irrelevant, like the constructor and close/dispose.

public class Log : IDisposable
{
    public enum LogType
    {
        Information,
        Warning,
        Error
    }

    private FileStream m_File;
    private TextWriter m_Writer;
    private string m_Filename;

    //this is used to hold sync objects per registered log file
    private static SortedList<string, object> s_SyncObjects = new SortedList<string, object>();
    //this is used to lock and modify the above variable
    private static readonly object s_SyncRoot = new object();

    public void WriteLine(Log.LogType MsgType, string Text)
    {
        //this is the problem i think, the lock isn't functioning correctly
        //see below this code for an example log file with issues
        lock (Log.s_SyncObjects[this.m_Filename])
        {
            this.m_Writer.WriteLine(DateTime.Now.ToString("MM/dd/yyyy HH:mm:ss:fffffff") + " " + MsgType.ToString() + ": " + Text);
        }

        return;
    }

    public void Open(string Filename)
    {
        //make filename lowercase to ensure it's always the same
        this.m_Filename = Filename.ToLower();
        this.m_File = new FileStream(Filename, FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
        this.m_Writer = TextWriter.Synchronized(new StreamWriter(this.m_File) { AutoFlush = true });

        //lock the syncroot and modify the collection of sync objects
        //this should make it so that every instance of this class no matter
        //what thread it's running in will have a unique sync object per log file
        lock (Log.s_SyncRoot)
        {
            if (!Log.s_SyncObjects.ContainsKey(this.m_Filename))
                Log.s_SyncObjects.Add(this.m_Filename, new object());
        }
    }
}

To test this I'm creating 3 instances of the logger pointing to the same log file, creating 30 threads and assigning each thread one of the loggers (in order 1,2,3,1,2,3), then I run all 30 threads until I press q.

This works great for writing line by line in a log file and keeping the times the writes happen in the correct order but here is what I get in the log file. It seems that the thread overwrites a portion of the log file and it seems to happen with different instances of the logger on different threads, never the same instance of the logger on different threads. The log file below has the time the entry was created, the logger ID (1 based), the thread ID (0 based) and the message "test".

08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3469116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3479116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3479116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3479116 Information: LOGID: 1, THREADID: 9, MSG: test
08/27/2012 11:47:34:3479116 Information: LOGID08/27/2012 11:47:34:3479116 Information: LOGID: 3, THREADID: 23, MSG: test
08/27/2012 11:47:34:3479116 08/27/2012 11:47:34:3509118 Information: LOGID: 1, THREADID: 0, MSG: test
08/27/2012 11:47:34:3509118 Information: LOGID: 1, THREADID: 0, MSG: test
08/27/2012 11:47:34:3509118 Information: LOGID: 1, THREADID: 0, MSG: test
08/27/2012 11:47:34:3509118 Information: LOGID: 1, THREADID: 0, MSG: test
08/27/2012 11:47:34:3509118 Information: LOGID: 1, THREADID: 0, MSG: test

Notice that 2 of the lines have been mangled. I'm guessing this is due to the locks not working properly, or my misuse of the locks. I would also prefer not to use queuing or any kind of singleton. This behavior doesn't seem to happen if I change the lock within WriteLine to the m_SyncRoot variable and make it non-static. I have no idea why that works but to me it seems like that is not what I want to do. I also don't want to lock on a static m_SyncRoot alone because then if I have 3 instances of the logger pointing to 3 different log files then each one will block the other for no reason.

I'm so lost on this, am I completely screwing this up?

In case anyone needs it, here is the test class for generating the threads

public class LogTest
{
    private Log m_Log1;
    private Log m_Log2;
    private Log m_Log3;
    private Thread[] m_Threads;

    private const int THREAD_COUNT = 30;
    private bool m_Done;

    public LogTest()
    {
        this.m_Log1 = new Log();
        this.m_Log2 = new Log();
        this.m_Log3 = new Log();

        this.m_Log1.Open("test.txt");
        this.m_Log2.Open("test.txt");
        this.m_Log3.Open("test.txt");

        this.m_Threads = new Thread[THREAD_COUNT];
        this.m_Done = false;
    }

    public void run()
    {
        for (int i = 0; i < THREAD_COUNT; i++)
        {
            Thread th = new Thread(new ParameterizedThreadStart(this.LogThread));
            this.m_Threads[i] = th;
        }

        for (int i = 0; i < THREAD_COUNT; i++)
        {
            int logId = 1;
            Log temp = this.m_Log1;
            if ((i % 3) == 1)
            {
                temp = this.m_Log2;
                logId = 2;
            }
            else if ((i % 3) == 2)
            {
                temp = this.m_Log3;
                logId = 3;
            }

            this.m_Threads[i].Start(new object[] { logId, i, temp });
        }

        ConsoleKeyInfo key = new ConsoleKeyInfo();
        while ((key = Console.ReadKey()).KeyChar != 'q')
            ;

        this.m_Done = true;
    }

    private void LogThread(object state)
    {
        int loggerId = (int)((object[])state)[0];
        int threadId = (int)((object[])state)[1];
        Log l = (Log)((object[])state)[2];

        while (!this.m_Done)
        {
            l.WriteLine(Log.LogType.Information, String.Format("LOGID: {0}, THREADID: {1}, MSG: {2}", loggerId, threadId, "test"));
        }
    }
}

EDIT: edited to change static m_ to s_ as suggested and added the AutoFlush property to the StreamWriter; setting it to true... still does not work.

Answer 1

I figured out the problem!

The thread synchronization works as it should and so does the TextWriter.Synchronized() so the problem isn't really the threads at all. Take this into account:

I create 3 instances of the Log class and point them all to "test.txt"

Log log1 = new Log();
Log log2 = new Log();
Log log3 = new Log();

log1.Open("test.txt"); //new file handle as instance member
log2.Open("test.txt"); //new file handle as instance member
log3.Open("test.txt"); //new file handle as instance member

In each call to Open() I am opening a new file handle to the same file, so I have 3 unique and separate file handles. Each file handle or Stream has it's own file pointer which seeks along the stream as I read or write.

So, if we have the following:

log1.WriteLine("this is some text"); //handled on thread 1
log2.WriteLine("testing"); //handled on thread 2

If Thread 1 starts to write to the file and completes the file contents will be

this is some text

When Thread 2 starts to write, because the file handles and streams are unique the current location of log1's file pointer is at 16 and log2's is still at 0 so after log2 is done writing, the resulting log file will read:

testing some text

So, all I need to do is make sure I open only 1 unique FileStream per log file and do the synchronization like I have been. Works great now!

Answer 2

I think your lock is working fine, but according to the documentation, TextWriter.Flush doesn't actually do anything, so it isn't actually flushing the buffer before you release the lock. Here's the [link]. 1

It looks like you can fix the problem by using AutoFlush on the streamwriter in the Open method.

this.m_Writer = TextWriter.Synchronized(new StreamWriter(this.m_File){AutoFlush=true})