EntLib 2.0 (January 2006) - Logging Application Block - Thread safety

Topics: Building and extending application blocks, Logging Application Block
Oct 22, 2009 at 1:37 PM

Hi,

I am currently using an old version of the Enterprise Library in one of my applications and experienced a lot of problems with the Logging application block. Let me explain you my design at first:

- the application consists of multiple components and a windows service
- the windows service is logging to several different destinations (file, database, etc.), but some log entries should be processed asynchronously, so they are written to the MSMQ queue
- MSMQ distributor is used to process those entries from the queue. At the same time, our trace listeners might be logging to some other destinations (however, this should have no effect on my situation, because even if I change the configuration and only process those entries from the queue, the problem still occurs).

The thing is that when I increase the workload on the server, a few log entries are never processed on the MSMQ side. This is really weird, because it seems that they are written to the MSMQ, picked up, but never reach the appropriate trace listener. At first I thought that it must be a concurrency issue and so far this is the only hypothesis that might explain that weird behaviour. What should I have in mind when designing new trace listeners to be thread-safe? Is there any way for me to see why EntLib did not process a few entries?

I really need your help with this, because for the last few days I have been trying to put more diagnostic code to my application and EntLib and so far I still cannot find any single piece of information that would explain what the problem is. Any suggestions (except recommending to upgrade) are very, very welcome.

Thanks in advance for help.

Regards,
Snake_net

Oct 23, 2009 at 4:46 AM

Hi,

Do you have a tracelistener under the "Logging Errors & Warnings", this will log error encountered during the logging process. If there is none, please try and see if there's something you can pull out of it.

Valiant Dudan
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

 

Oct 23, 2009 at 12:51 PM

Hi,

I have already defined a new trace listener for this purpose, but nothing gets written to it. However, I was obviously wrong and searched for the problem in the wrong place. After adding more diagnostic code both to the application and EntLib I was proved that the message never gets written to the MSMQ queue. Right now, I do not know whether this is some kind of a problem related to the MSMQ trace listener, bug in my application or a concurrency issue. If a few threads might be logging to the same MSMQ via the same listener, is there anything specific that I need to do to support it? Do I have to manually synchronize them or does EntLib take care of it?

Thanks a lot for help!

Best regards,
Snake_net

Oct 26, 2009 at 3:14 AM

I believe entlib already takes care of it.  Did you use a BinaryFormatter for your MSMQ trace listener?  If yes, have you  tried successfully sending message to the queue using the regular code (using .NET's MessageQueue class)?

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

Oct 26, 2009 at 11:05 AM

Yes, I used the BinaryFormatter and what is really strange is the fact that it happens only to some of log entries. I mean, all other are written to the MSMQ successfully so this is not a problem with permissions or connectivity. I cannot definitely blame EntLib for this. Perhaps in some specific conditions my application is not logging such an event. Another hypothesis is that a few threads are trying to log to the MSMQ at the same time and it fails.

Any ideas?

Regards,
snake_net

Oct 26, 2009 at 5:26 PM

Hi,

I think I have just found a bug in this version of EntLib (January 2006). Please take a look at the source code and check the ReceiveQueuedMessages method located in the MsmqLogDistributor.cs file. What I can see is that the message is retrieved from the MSMQ by using the Peek method. Then the body is deserialized by using the Binary Formatter. Finally it is logged and in the end, it is removed from the MSMQ by invoking the Receive method on the message queue object. The real problem starts when messages with different priorities are placed in the queue. Why? Because according to the MSDN (http://msdn.microsoft.com/en-us/library/829zyck7.aspx):
1) Message Queuing orders messages in the queue according to priority and arrival time. A newer message is placed before an older one only if it is of a higher priority.
2) Therefore, repeated calls to Peek return the same message, unless a higher priority message arrives in the queue.

Imagine a situation when there are only messages with the low priority in the queue. Then the Peek method will return one of them (the first one) and according to the source code, the body of this message will be deserialized and logged. Finally the Receive method will be invoked. If in the meantime another message with the high priority was entered to the queue, Receive method will return and remove that message from the queue instead of the message that was initially processed (because MSMQ will place this message as the first one - according to the ordering information provided above). That is why some of my messages never reached the right Trace Listener while others might be logged twice.

A temporary workaround is to log all messages to MSMQ with the same priority, but I guess that the fix is quite simple. Before the Receive method is invoked, there should be a check whether the first message in the queue (retrieved by Peek) is the same which we have just processed. If not, it should not be logged and the processing should be restarted with the first message from the queue. Another option is to log this message and skip the Receive operation. However, then we would log the information twice, so there might be a need to keep such an information for further processing (to skip the message that has already been logged).

Could you please confirm this is a bug (since I might be wrong, of course) in EntLib and provide a patch for the community? I am pretty sure other people might experience similar problems in the future and since I know how long I was trying to find the root cause of my problem, I would like that app (MSMQDistributor) to be fixed.

Thanks in advance for help.

Kind regards,
snake_net

Oct 27, 2009 at 10:49 AM

Hi,

We'll investigate on this and provide you updates.

Valiant Dudan
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

Oct 28, 2009 at 4:16 AM

I think you have a point there snake_net.  We will confirm this with the EntLib team.

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

Oct 28, 2009 at 11:23 AM

Thanks for keeping me updated.

In my case, all problems have been solved by simply changing the configuration to log all entries to MSMQ with the same priority. Besides, a few lines of diagnostic code proved that a different message is processed and another one is removed from the queue (assuming that priorities of messages are different and I am referring here to the scenario described in one of my previous posts). Anyway, it is always better to double check. Thanks for your support.

Regards,
snake_net

Dec 17, 2009 at 10:18 PM

snake_net,

Thanks for reporting this. It does sound like a bug. We'll investigate and make sure it's fixed in the next version of EntLib.

We don't provide patches to old versions.

Grigori