c# multithreading -- really confused!

[inxanu]

Hi all,

I have several threads running (basically they are copying files from one place to another). I am using log4net for logging...However, sometimes i get a log4net error due to log file being used by other process. I thought about creating a method which will take care of the logging...all threads will used a delegate to call the method that does the logging

static readonly object lockerLog = new object();
public delegate void UpdateLogDelegate(string txt,string type)

public void LogInfo(string txt, string type)
        {
            lock (lockerLog)
            {
                switch (type)
                {
                    case "ERROR":
                    Logging.log.Error(txt);
                    break;
 
                    case "DEBUG":
                    Logging.log.Debug(txt);
                    break;
                }
 
            }
 
        }
 

My question is: as the code stands right now, I thread might have acquired the lock on the call to the logging, but a second thread might have come along and modified the method parameters "txt" and "type", right? Is there a way of locking the entire method?

I think that another option could be to create a class to hold the txt and type and pass the object to the method

public void LogInfo(LogText lt)
        {
            lock (lt)
            {
                switch (lt.type)
                {
                    case "ERROR":
                    Logging.log.Error(lt.txt);
                    break;
 
                    case "DEBUG":
                    Logging.log.Debug(lt.txt);
                    break;
                }
            }
 
        }
 

Or just locking the logger

class Logging
{
public static readonly ILog log = LogManager.GetLogger(typeof(Logging));
Logging() {}
public string Initialize()
{
.....
}
}
 

thus when I called it from another class I do:

lock(Logging.log)
{
Logging.log.Info("hopefully there is a lock in the log right now ...");
}
 

Anyone knows what will be the proper way of doing this, if ANY of the ones I have mentioned? I am new to threading and feel a bit confused

Cheers

[tlhintoq]

I've looked at, but not played with Log4Net. Instead I just do my own logging. In my function I raise an event with the log text. My logger is subscribed to the event. Thus it is listening for the next item to log, not being commanded to log *now*. Could something similar work for you? Raise a custom event with the logging data so that a single method then funnels the events to Log4Net?

[mldisibio]

At the heart of the problem, no matter what logging API you use, is the fact that a single text stream is being accessed by more than one thread.
Locking is a good start, but remember

lock(someLocker){do logging}

means that any entering the "do logging" block will only proceed when the previous block is completely finished. Effectively, you will block logging threads one at a time, undermining the purpose of multi-threading.

There could be several solutions, including creating an "asynchronous" Appender in log4net, but at a high level I would recommend what tlhintoq said with one addition:

If you set up an event that your logging object can listen to, your classes will fire a "LogTextIsReady" type of event and then carry on their task. The logging listener alone then becomes responsible for maintaining the synchronous access to the textstream when asynchronous writes are requested.
(Before I go on, let me mention that you will want to try to make the "LogTextIsReady" event as globally accessible as possible so that you are not repeating the same event in all your individual task classes. Use an interface or perhaps a static class or singleton object.)

At a basic design, your logging listener really just needs a thread signal, such as an System.Threading.AutoResetEvent. This is called a EventWaitHandle and allows an operation to proceed only when the previous thread or block of code finishes and tells the signal that the next block or thread may proceed.

In the case of a logger, each write method will call "WaitOne()" - meaning wait until the previous write is finished. When it finishes writing, it calls "Set()" to let the signal know to allow the next thread to start.
So your logger (which can still be a log4net logger) will be queuing up texts to write to the stream, one at a time, but because your logger is event driven, the classes and threads which called the listener do not need to wait for the event handler to complete.

By following this model, you will probably then only have one logger instance, which means you lose the log4net "named logger" and implicit tracing feature. If that is important to your application, as mentioned you can try encapsulating the above thread control into a custom Appender or Forwarder.

[inxanu]

Many thanks for your input...It has been really helpfull. I will have to think about changing the logging. But one thing that intrigues me:

At present I am locking the logger

lock(Logging.log)

yet i still got this error:

log4net:ERROR [FileAppender] Unable to acquire lock on file d:\logfiles\
WSFileCopier.log. The process cannot access the file 'd:\logfiles\WSFileCopier.log' because it is being used by another process.

This is my log4net appender in the config file:

    <appender name="RollingFileAppender" type="log4net.Appender.FileAppender">
      <file value="d:\logfiles\WSFileCopier.log" />
      <appendToFile value="true" />
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
      </layout>
    </appender>
 

Also my log4net appender has been configured using the minimal locking which allows multiple processes to write to the same file (eventhough at this point I am only using one...) so, why am I getting this?

[mldisibio]

Not sure why. You might try removing your lock altogether just to see if it is your own lock that is causing the access denial. Does this error happen before even the first write, or is something being written to file, and this happens when a second process attempts to write?

Don't forget, locking just says: "you can't have access to this object until the lock is released." That does not mean the caller will wait for it to be released...you need the WaitHandle mechanism to actually make a thread wait for a lock to be released. So while locking the logger makes sure that no two processes are accessing the stream at the same time, it does not force a thread to wait. Therefore, as soon as the second call attempts to access the stream, it is locked out and could easily return immediately with a message "cannot acquire lock."

Of course, it could also be something silly, like another text editor or application which has an exclusive lock on your log file...this is unlikely but it happens sometimes.

Finally, some authors will recommend...although it is not a hard and fast rule...that you not lock on your object doing the work, but rather on a separate object whose sole purpose is to server as a lock. So instead of

lock(Logging.log){...}

do (at global or static level)

object loggingLocker = new object();
 

and in any code block:

lock(loggingLocker){log.WriteInfo()...etc}

[inxanu]

"Does this error happen before even the first write, ..." --> No
"or is something being written to file, and this happens when a second process attempts to write?" --> No, I do not have any more processes writting to this file, or at least I shouldn't. I am using the lock()... I will create a global lock as you suggest.

Also
"Don't forget, locking just says: "you can't have access to this object until the lock is released."

I have to create up to 100 threads to do different jobs. Once a thread finishes its job, it updates their status. The thread status info is being held in an ArrayList called jobsToDo. At present I was just using a lock (without any signalling) thinking that the lock already synchronized the threads

public void UpdateJobList(int jobid)
        {
           //Update jobList
            lock (jobsToDo)
            {
                bool bFound = false;
                //Find the job on the list and update it
                foreach (Jobs j in jobsToDo)
                {
                    if (j.JobId == jobid)
                    {
                        bFound = true;
                        j.ThreadId = -1;
                        j.Status = "Finish";
                        Logging.log.Debug("Job id \"" + j.JobId + "\" status has been updated to \"Finish\"");
            Thread.Sleep(5000); //just to be sure that more than one thread will reach this method while
                        //one thread in in here doing its job.
                        break;
                    }
                }
                if (!bFound)
                {
                    Logging.log.Error("Could not found job id \"" + jobid + "\" in job list");
                }
            }
        }
 
 

Now, I am checking the log and everythings seems to be fine. How can that be!? Please note how thread Job 2, Job 3, Job 4 arrive to the lock statement, and they wait for it (or at least they seem to do that) untill Job 1 releases the lock, then Job 2 goes in and updates it is status, then after 5 sec, Job 3 goes in ...and so on...this is the expected behaviour I want...However, it seems that a lock by itself should not produced this output right? HELP! please, I really need to understand why this is happening...

Log:

2009-03-02 18:53:04,498 [Job 1] DEBUG ClassLibrary1.Logging - Going to update job list for job id "1"
2009-03-02 18:53:04,498 [Job 1] DEBUG ClassLibrary1.Logging - Job id "1" status has been updated to "Finish"
2009-03-02 18:53:05,483 [9] DEBUG ClassLibrary1.Logging - Job Id 2 has been started
2009-03-02 18:53:05,498 [Job 2] DEBUG ClassLibrary1.Logging - Going to update job list for job id "2"
2009-03-02 18:53:06,498 [9] DEBUG ClassLibrary1.Logging - Job Id 3 has been started
2009-03-02 18:53:06,498 [Job 3] DEBUG ClassLibrary1.Logging - Going to update job list for job id "3"
2009-03-02 18:53:07,498 [9] DEBUG ClassLibrary1.Logging - Job Id 4 has been started
2009-03-02 18:53:07,498 [Job 4] DEBUG ClassLibrary1.Logging - Going to update job list for job id "4"
2009-03-02 18:53:08,514 [9] DEBUG ClassLibrary1.Logging - Job Id 5 has been started
2009-03-02 18:53:08,514 [Job 5] DEBUG ClassLibrary1.Logging - Going to update job list for job id "5"
2009-03-02 18:53:09,498 [Job 2] DEBUG ClassLibrary1.Logging - Job id "2" status has been updated to "Finish"
2009-03-02 18:53:09,530 [9] DEBUG ClassLibrary1.Logging - Job Id 6 has been started
2009-03-02 18:53:09,530 [Job 6] DEBUG ClassLibrary1.Logging - Going to update job list for job id "6"
2009-03-02 18:53:10,530 [9] DEBUG ClassLibrary1.Logging - Job Id 7 has been started
2009-03-02 18:53:10,530 [Job 7] DEBUG ClassLibrary1.Logging - Going to update job list for job id "7"
2009-03-02 18:53:11,530 [9] DEBUG ClassLibrary1.Logging - Job Id 8 has been started
2009-03-02 18:53:11,545 [Job 8] DEBUG ClassLibrary1.Logging - Going to update job list for job id "8"
2009-03-02 18:53:12,530 [9] DEBUG ClassLibrary1.Logging - Job Id 9 has been started
2009-03-02 18:53:12,545 [Job 9] DEBUG ClassLibrary1.Logging - Going to update job list for job id "9"
2009-03-02 18:53:13,545 [9] DEBUG ClassLibrary1.Logging - Job Id 10 has been started
2009-03-02 18:53:13,561 [Job 10] DEBUG ClassLibrary1.Logging - Going to update job list for job id "10"
2009-03-02 18:53:14,498 [Job 3] DEBUG ClassLibrary1.Logging - Job id "3" status has been updated to "Finish"
 

[mldisibio]

I think you are good. Let me explain why I think this works. Mind you, I am not an absolute expert or authority on the subject.

In your previous example, you were locking on the logger itself (Logging.log). Since this object owns the access to the log file, a lock on it basically locks out the file as well, no matter how access rights are configured initially.
So probably your second and third job come along, attempt to get a handle to Logging.log or its underlying file, and are told "sorry, I'm locked" so they return with "cannot access file."

In your more recent example, you are locking on the ArrayList (which by the way has some inherent thread safety built in). The logger itself is not locked. So Job 2 and Job 3 come and are told: "Wait, you can enter this method "UpdateJobList" as soon as the ArrayList is available." By the time they are allowed to call on the logger itself, the file has released its previous write lock.

You have the simplest locking model and it seems to work fine. I would leave it alone. Signalling would add some robustness...for example, if your application needed to terminate, you might be able to check if some log writes were still pending before terminating completely...but you can add those enhancements later.

For a great reference to threading and locking, I highly recommend:
http://www.albahari.com/threading/ [Threading in C# by Albahari]

[mldisibio]

@mldisibio
You proved that what I said is not entirely correct. How about if I just quote an expert...(source Albahari - same link as above):

The lock statement (aka Monitor.Enter / Monitor.Exit) is one example of a thread synchronization construct. While lock is suitable for enforcing exclusive access to a particular resource or section of code, there are some synchronization tasks for which it's clumsy or inadequate, such as signaling a waiting worker thread to begin a task.

The Win32 API has a richer set of synchronization constructs, and these are exposed in the .NET framework via the EventWaitHandle, Mutex and Semaphore classes. Some are more useful than others: the Mutex class, for instance, mostly doubles up on what's provided by lock, while EventWaitHandle provides unique signaling functionality.

[inxanu]

Hi mldisibio,

I did in fact read through the information you suggest (Albahari) thats why I thought that by locking the arraylist i was taking care of the thread synchronization. Why was I still unsure?
1) It is the first time I am using multithreading and ...
2) English is not my first language, thus sometimes I can misinterpret information (which now has been totally clarify, a big THANK YOU!)
3) As with the vast majority of information on internet, you are never sure the level of accuracy

Anyway, I REALLY APPRECIATE YOUR HELP :)

Now, my logging...I am going to try using a global lock to see how it goes...if i still get the "random" (I say random because I cannot pint point when it happens, also I cannot recret it) I will have to implement the logging as you suggested. I tried removing the lock on the logging but I was still getting the error.

Also you said
[quote]
you were locking on the logger itself (Logging.log). Since this object owns the access to the log file, a lock on it basically locks out the file as well, no matter how access rights are configured initially.
[quote]
If we go to the basics one moment, basically, whenever there is a static field which is being access by more than one thread, a lock should be used, right?Then,my logger log is being accessed by more than one thread, shouldnt i use a lock on it? Isnt' the fileappender the one that it is lock, and thread-safe?Isnt the fileappender something totally different than my logger?My understanding was that the minimal lock file appender allows, for instance, two different applications, each with it is on logger, to write to the same log file safely...please correct me if I am wrong

Cheers

[mldisibio]

Couple of things:
1. The Log4Net API explicitly says that the FileAppender is NOT safe for multithreaded applications (which just means it does not come out of the box with thread safety...you can still build thread safety around it, as you are doing).

2. The MinimalLock configuration basically says: "for any write operation, acquire the lock to the underlying stream, write, release the lock." This means that two threads could write to the same file during the same overall job - but not at the same time! Writes still happen one after the other. But in an ExclusiveLock, the first thread would actually have to call CloseFile() before another thread could write to the same file. (Its real purpose is to allow one of those threads to move, copy or even delete the file without stopping logging entirely.)

3. Just a clarification: when you lock a primitive value, such as an int or a boolean, you are telling the runtime: "do not allow any caller to change this value until I release the lock on it." So a very simple example:

static int MyInt;
static void SaveWorldIfTwo(){
MyInt = 2;
if((2/MyInt) == 1) SaveWorld();
}

If MyInt is accessed by multiple threads, then without locking, another thread can change MyInt to zero between the call "MyInt = 2" and "2/MyInt" leading to a "division by zero" exception and the world not being saved.

However, when you lock on an object or you lock a block of code, then the focus is not on preserving a primitive value, but rather on not letting other code have access to that object or block of code until the lock is released. In some cases, you might even cause a thread to hang because you have locked an object (such as a logger) and perhaps in the case of third party libraries or in an event driven model, other classes need to access it before it exits your lock, but they cannot.

4. Finally, in terms of the relationship of the log4net ILog, Appender and such, those are great questions I am not qualified to answer. The API makes them appear to be completely separate objects, but it is quite possible they are each abstractions which have underlying dependencies. And in the case of classes which access file streams, it is very likely that the stream locking is shared among the different API layers.