Rolling over TextWriterTraceListner logs

April 30th, 2004 Leave a comment Go to comments

Do you utilize the Trace and Debug classes from the System.Diagnostics namespace? Do you use a TextWriterTraceListener to log your messages? Have you ever wondered why the TextWriterTraceListener doesn’t have the ability to roll over its logs at certain intervals?


I’ve developed a number of server-based applications in which we employed the abilities of the System.Diagnostics classes to trace certain application events. Whether its for debugging purposes or to report unexpected events. Its easy enough to utilize the TextWriterTraceListener to capture these messages and easily view them when needed. Depending on what types of events your tracing and at what levels your tracing at (see TraceSwitch), the trace log can get quite large for a server-based application. I would find it very beneficial if the TextWriterTraceListener would roll over its logfile at certain intervals, say on a weekly, daily, or hourly basis. One of my mottos is: If it doesn’t exist, build it!


Here is a simple wrapper for the TextWriterTraceListener that rolls over each day. I’m a little reluctant in posting source code on a blog because I know there are some people who will look at it and say, “Why on earth did you do it that way, you idiot!”. But that’s allright. I can take the criticism. As a matter of fact, that’s why I’m posting this. For one, I want to share this with whomever finds it useful and I also want someone to pick it apart and start a dialogue to discuss if there’s a better solution.


There is one question I hope the blog community can help me come to a conclusion on. What happens when the log file rolls over and another process is trying to write a trace message during the rollover? Does that message get lost? Can I solve it through thread synchronization? Is this even an issue?


Anyhow… here’s the code for the RollOverTextWriter:


using System;
using System.Diagnostics;
using System.IO;


namespace Corgan
{
public class RollOverTextWriter: System.Diagnostics.TraceListener
{
string _fileName;
System.DateTime _currentDate;
System.IO.StreamWriter _traceWriter;

public RollOverTextWriter(string fileName)
{
// Pass in the path of the logfile (ie. C:\Logs\MyAppLog.log)
// The logfile will actually be created with a yyyymmdd format appended to the filename

_fileName = fileName;
_traceWriter = new StreamWriter(generateFilename(), true);
}

public override void Write(string value)
{
checkRollover();
_traceWriter.Write(value);
}

public override void WriteLine(string value)
{
checkRollover();
_traceWriter.WriteLine(value);
}

private string generateFilename()
{
_currentDate = System.DateTime.Today;

return Path.Combine(Path.GetDirectoryName(_fileName),
Path.GetFileNameWithoutExtension(_fileName) + “_” +
_currentDate.ToString(“yyyymmdd”) + Path.GetExtension(_fileName));
}

private void checkRollover()
{
// If the date has changed, close the current stream and create a new file for today’s date
if (_currentDate.CompareTo(System.DateTime.Today) != 0)
{
_traceWriter.Close();
_traceWriter = new StreamWriter(generateFilename(), true);
}
}

protected override void Dispose( bool disposing )
{
if( disposing )
{
_traceWriter.Close();
}
}
}
}


Categories: .NET Development
  • http://

    Cool – I just did something like this recently too – called it CyclicTraceListener. I’ve got some app.config appSettings that let the user adjust how many files of what size are kept in the ‘live’ log files folder – and then roll these files off into an archive folder – in compressed format using ICSharpCode.SharpZipLib.Zip when that limit is reached.

  • Dave Bost

    That’s a great idea Glen. I wanted to make the code I posted as simple as possible to get the point across, but I’ll take your config ideas and roll them into my app release.

    I don’t suppose you could share your code with the rest the community, could you? ;)

  • http://

    I’m guessing “another process” means another thread? If you were referring to several processes attempting to write to the log file on their own, then it’s up to the OS to synchronize access. I’m not an expert, but I would guess opening a file for writing by several processes is not allowed.

    Anyway, if a situation with several threads attempting to use RollOverTextWriter to log and roll over happens to take place at the same time as another thread attempts to write there are several possibilities of what will happen:

    1) Roll over completes in one thread, and then another thread gets to it, sees new date and continues normally. (everything is fine)

    2) One thread closes and recreates the writer while another thread suspended right when it has passed IF check, but didn’t get to close the writer yet. Then suspended thread resumes, closes the writer, but recreates it right back. 1st thread didn’t get to write yet, or managed to finish writing before the 2nd thread get to close the stream. (again, everything is fine)

    3) Similar to above, but a little different:

    a)1st thread recreates writer while 2nd thread just got ready to do the same.

    b)1st thread suspended. 2nd thread closes the writer.

    c)2nd thread suspended, first thread attempts to write to the closed writer and throws exception.

    d)2nd thread resumes, recreates the writer and attempts to play innocent.

    I think this is it, but I could be missing something. Anyway the point is that an erroneous situation can arise, although the probability of that happening is quite small. In any case I can think of several solutions:

    1) Catch exception when attempting to write, assume this erroneous situation occurred, try again (I would advise against this method).

    2) Do thread synchronization, possibly sacrificing some performance. Different ways are possible here, but most likely will add some overhead which probably doesn’t matter in all but the most log intensive applications.

    3) In rollback function do something like this:

    StreamWriter tempWriter = _traceWriter;

    _traceWriter = new StreamWriter(generateFilename(), true);

    tempWriter.Close ();

    This should assure that the stream is only closed when replacement is in place. Although it looks OK I have just came up with this and thus have not tested (in fact I can’t be sure it compiles), so it might not fix the problem or introduce some other problems (Like it doesn’t take into account problems that could arise if two threads attempt to open a file simultaneously. One should win, and another will probably throw an exception).

    Well, I hope this was helpful.

  • Matt

    log4net might be a better idea, as it has rolling log files already implements. log4net is also a clone of log4j, a standard almost in the Java world

    http://logging.apache.org/log4net/

    http://logging.apache.org/log4net/release/config-examples.html#HC-29493424

    http://logging.apache.org/log4j/

  • Jim Arnold

    +1 for using log4net instead.

  • http://

    Someone recommended log4net on the post over at TheServerSide.NET (http://theserverside.net/news/thread.tss?thread_id=25650) and I will definitely check it out.

    As I stated on the discussion thread at TheServerSide.NET, this was an excercise on my part to see what trouble you could get into, if any, by implementing such harmless looking functionality. I’m all about not trying to re-invent the wheel and will most likely use what log4net has available for my production apps.

    Thanks for the recommendation.

  • http://

    I’ve written a rolling file logger in C#.NET. The way I handled multi-thread access issues was as follows:

    1) Make the current logging file something like “log.txt”.

    2) When a need arises to roll over, copy the contents of log.txt to a file named something like “log-20040504122305.txt”.

    3) Next truncate the “log.txt” file.

    4) Surround the Write logic with a lock() block.

    By taking this approach you never risk the log file removal and subsequent file locking errors. Also since the Write logic is locked, there is no possibility of log contamination.

  • http://

    I posted a follow up message on theserverside.net, but I’d like to ask the same question here:

    does MS already have a solution that’s like Log4net or will MS introduce one in .NET 2.0?

    Because I’m trying to avoid spending time using Log4net, then MS got its solution already or soon.

    Thanks!

    Ray.

  • Tom Gilkison

    If you decide on log4net for an ASP.NET application, read my log4net tutorial:

    log4net Tutorial: Using log4net in an ASP.NET Application

    http://tom.gilki.org/programming/net/120604/

    Cheers!

  • Joe

    Has anyone else needed to add “_traceWriter.Flush()” in the Write and WriteLine methods? And, are log4net and NLog still being maintained? Are there better alternatives now?

  • Balaji

    its a wonerful article. I have used this logic to create my custom trace listener. I agree with joe. You need the flush() call in write and writeline method. if u dont call flush() streamwriter holds all the things in buffer and writes only when it gets closed. Close() happens only when next day;s file gets created. So if you want to see entries in log file then and there u need to call flush()

  • geoff

    Nice. In answer to your questions, your class is not thread-safe, but it could be with a few minor changes. By default, the StreamWriter class is not thread-safe so your Write() and WriteLine() methods are not thread-safe. Unfortunately, the StreamWriter class does not expose a Synchronized property, so the easiest thing to do is to declare a member variable called padlock that is just an object, i.e.

    private object _padLock = new object();

    In your adjust your write() method to look like:

    public override void Write(string value)
    {

    lock(_padLock)

    {

    checkRollover();
    _traceWriter.Write(value);

    }
    }

    Do the same for your WriteLine() method.

    Your CheckRollover method is also not thread-safe, however, if you implement the above locking in your write methods and if its true that only the write methods call CheckRollover(), then nothing else needs to be done. Nevertheless, I would re-write CheckRollover() to look like the below. This way, anything can could call CheckRollover() in the future. If there were a synchrnoized wrapper in the StreamWriter class and you were to use it instead of locking, then CheckRollover would cause a race condition without the locking below.

    private void checkRollover()
    {
    // If the date has changed, close the current stream and create a new file
    if (_currentDate.CompareTo(System.DateTime.Today) != 0)
    {
    lock(_padlock)
    {
    if (_currentDate.CompareTo(System.DateTime.Today) != 0)_
    {
    _traceWriter.Close();
    _traceWriter = new StreamWriter(generateFilename(), true);
    }
    }
    }
    }

    Note that in .Net its okay to have nested locks on the same object (i.e., WriteLine locks padlock and then calls checkRollover, which also locks on _padlock, but it won’t be blocked.

    Anyway, I am going to use this. Thanks.