We had a problem on our windows service, where for some reason after about a half an hour I couldn’t see any processings in the logs anymore.
Till that point nothing was wrong. When I tried to stop the service, I had the error: “error 1053 the service did not respond to the start or control“. In the event log I could sometimes find “Problem: The Windows Search service terminated unexpectedly“.
I’ve tried many things. I thought that maybe the synchronization of the task processing is wrong. Or that a lock was on a wrong place causing a deadlock somehow and so on. After many tries and fixes (which certainly did good to the service) I decided to create a memory dump from the service on the server.
I started Windbg on it and immediately recognized that I have tons of threads (over 2000). Ran !syncblk but didn’t find any blocks between them. I took a look at the stack of them and on the top I’ve seen a lot of NtWaitForMultipleObjects.
Ok what causes that?
Parallel to that suddenly the situation happened locally. I was really happy. Immediately attached a debugger and searched the threads for something with Wait in their stack. I’ve found them all – thousands of them – they contained “Monitor.Wait()“.
Ok now I knew what to search for. Restarted the service and gone step by step through the methods watching parallel the Threads window with the filter “Monitor.Wait()“. I was excited to wait for the first occurrence . It came fast. When I logged an entry. I just have started to comment out the trace listeners from the Enterprise Library logging configuration section. In this way I pointed out the EmailTraceListener. Checked it with dotPeak – found that the SmtpClient (used by it) uses Timers… Probably this was it… Now we are probably going to think on, how to send log emails after that… Hope it helped someone.
In the end it turns out that the correct usage of the Enterprise Library Logging solves the most of the problem. The problem came when we have been using the disposable logwriter without disposing:
var logger = new LogWriterFactory().Create(); logger.Write(logEntry);
The correct usage is when you set the log writer somewhere in the beginning of your processing (or application start for ASP.NET) and then using always static Logger.LogWrite as follows:
// Registering the log writer somewhere in the beginning of the process: Microsoft.Practices.EnterpriseLibrary.Logging.Logger.SetLogWriter(new LogWriterFactory(configurationSource).Create()); // Creating logs throughout the app Microsoft.Practices.EnterpriseLibrary.Logging.Logger.Write(logEntry);
The above initialization can be extended if using configuration described here.