views:

49

answers:

2

I'm using Visual Studio 2010 to write a simple C#/.NET GUI app, wherein I use a Logger class to write tracing/debugging info to a single file from within all of the various classes of the project. (See source code below.)

Each class's constructor writes an entry to the log when one of its object types is instantiated. One of those classes is a custom GUI controller component (class FileAttributesCtl), which is contained in a couple of the GUI forms used by the program.

The problem I'm having is that two logfiles are created, about 200 msec apart. The first logfile contains (only) a message that a FileAttributesCtl object has been constructed, and the second contains all of the other messages written to the (supposedly) shared logfile output stream. So every time I execute my project code, I get two logfiles.

Stranger still, every time I rebuild my project (F6), a logfile is created for the FileAttributesCtl object, indicating that an control object of this type is actually instantiated during the build process.

This apparently has something to do with threading. If the logfile is not named uniquely (i.e., if I do not append a unique date/time string to the filename), I get an exception, indicating that more than one process (which is actually the VS2010 process itself) is currently using the file.

So my question is: How do I get the singleton object to actually be a single object?

A secondary question is: Why is VS2010 acting this way?

//----------------------------------------
// Logger.cs
class Logger
{
    // Singleton object
    private static Logger   s_logger =
        new Logger("C:/Temp/foo.log");

    public static Logger Log
    {
        get { return s_logger; }
    }

    private TextWriter  m_out;

    private Logger(string fname)
    {
        // Add a date/time suffix to the filename
        fname = ...;

        // Open/create the logging output file
        m_out = new StreamWriter(
            new FileStream(fname, FileMode.Create, FileAccess.Write,
                FileShare.Read));
        m_out.WriteLine(DateTime.Now.ToString(
            "'$ 'yyyy-MM-dd' 'HH:mm:ss.fff"));
    }

    ...
}

//----------------------------------------
// FileAttributesCtl.cs
public partial class FileAttributesCtl: UserControl
{
    private Logger  m_log = Logger.Log;

    public FileAttributesCtl()
    {
        m_log.WriteLine("FileAttributesCtl()");  //Written to first logfile
        InitializeComponent();
    }

    ...
}

//----------------------------------------
// FileCopyForm.cs
public partial class FileCopyForm: Form
{
    private Logger  m_log = Logger.Log;

    public FileCopyForm()
    {
        // Setup
        m_log.WriteLine("FileCopyForm()");       //Written to second logfile

        // Initialize the GUI form
        m_log.WriteLine("FileCopyGui.InitializeComponent()");
        InitializeComponent();
        ...
    }

    ...
}

Note: This is very similar to a question from Dec 2009:
http://stackoverflow.com/questions/1946630/access-to-singleton-object-from-another-thread
but it does not have the answers to my question.

Update

Further investigation shows that the VS2010 is indeed instantiating the custom component during the build, probably so that it can render it in the Designer window.

Also, there are indeed two separate threads calling the Logger constructor (each having a different ManagedThreadID).

Using a static class initializer to construct the singleton object does not work; I still get two logfiles.

Resolution

Upon closer examination, I notice that the custom control is getting instantiated twice, and this is being shown in both logfiles.

Therefore I think the problem is entirely due to the fact that VS instantiates the custom control object prior to executing the program that results in the first logfile being created. The second logfile is then created after the program starts normal execution.

Thus the first logfile is simply a side effect of the build process, and does not really have anything to do with multiple threads executing during normal program operation.

The obvious solution is to remove all logfile side-effect code from the component constructors. Or simply just ignore the first logfile altogether.

+1  A: 

It could very well be that Visual Studio is building your UI component (to display in the designer) and in the process, your constructor is getting called which is why you're seeing that log file during the build process.

BFree
That sounds reasonable, since when I previously had an exception (because the filename was always the same, without a uniquefying suffix), the VS designer window displayed an error, being incapable of redrawing the form. This seems like an immensely stupid way of doing it, though, since creating the bare component could cause side effects, some of which could be harmful if the main program form has not been created also.
Loadmaster
@Loadmaster The designer is there to give you a preview of the form's behavior when it's instantiated in your application. The most accurate way to do this is to use the code you've specified for instantiating - what better than by showing you the real thing?
Jake
@Loadmaster The constructor isn't the correct place to do side effect causing operations. That is the `Load` event of the form.
BioBuckyBall
@Lucas: Non-form components don't have Load events (as far as I know).
Loadmaster
@Loadmaster: My mistake, my eyes missed the fact that these are UserControls. Regardless, UserControls also have Load events you can hook into.
BioBuckyBall
+1  A: 

Static data + threads = trouble

You need to synchronize access to the singleton (and initialization of the singleton).

A static constructor may help

class Logger
{
    private static Logger
    static Logger()
    {
        s_logger = new Logger("C:/Temp/foo.log");
    }

    // ...

or better yet use a logging library (log4net) that handles all this stuff for you.

As for VS builds causing a log to be created, I'm not surprised. It is probably instantiating the forms to discover information about your forms via reflection.

update per comments

@LoadMaster "The static class initializer does not work. I added more info to the logfile output to include the current thread's ManagedThreadID, and sure enough, there are two different thread IDs creating the two logfiles."

That's strange. Per MSDN

The static constructor for a class executes at most once in a given application domain. The execution of a static constructor is triggered by the first of the following events to occur within an application domain:

  • An instance of the class is created.
  • Any of the static members of the class are referenced.

Your thread must have moved AppDomains or there is some code missing from your snippets.

BioBuckyBall
I didn't need a complex logging class, which is why I built my own very simple one. I intend to remove it from the final code anyway.
Loadmaster
And hence, you will end up reimplementing half of it :)
BioBuckyBall
The static class initializer does not work. I added more info to the logfile output to include the current thread's `ManagedThreadID`, and sure enough, there are two different thread IDs creating the two logfiles.
Loadmaster
Doh. It's (now) obvious that the first logfile (and the first control object instatiation) is simply a byproduct of the build process. See my Resolution above.
Loadmaster
There you go, that's how it got past the static constructor... more than one AppDomain. Glad you solved it.
BioBuckyBall