Getting multiple log entries :(

Topics: Logging Application Block
Aug 15, 2008 at 4:30 PM
Hi, i have been adding simple extensions to Logging block and everything seems to have worked. I just noticed this odd behaviour that at first i thought was because of my coding but i removed all my code and just use the core functioanlity of the Enterprise library and this is still occuring. Consider the following code

            using (Microsoft.Practices.EnterpriseLibrary.Logging.Tracer t = new Microsoft.Practices.EnterpriseLibrary.Logging.Tracer("General"))
                LogEntry entry = new LogEntry("Test M","Business",(int)Priority.High,(int)EventType.Default,TraceEventType.Information,"",new Dictionary<string,object>());
                LogEntry entry2 = new LogEntry("Test N","DataAccess",(int)Priority.High,(int)EventType.Default,TraceEventType.Information,"",new Dictionary<string,object>());

I want to log, two events inside a tracing operation. Everything gets logged fine but when i look at the log table, i see multiple records.

So the output of above code execution is

Start Trace: Activity 'ed5c6b14-0fe2-4996-98f6-317a81871d93' in method 'LoggingTest.Form1.button1_Click' at 79525800710422 ticks General
Test M General
Test M Business
Test N General
Test N DataAccess
End Trace: Activity 'ed5c6b14-0fe2-4996-98f6-317a81871d93' in method 'LoggingTest.Form1.button1_Click' at 79526999038132 ticks (elapsed time: 0.4 seconds) General

As you can see that for Trace operation , "General", i have an extra log entry. I dont want this, i only want to log

Start Trace ---- General
End Trace ---- General

Am i doing something wrong or is this a default behaviour?

Aug 15, 2008 at 8:52 PM

If you provide several categories and the categories share trace listeners in your app's configuration you will get duplicated entries. Is that your case?

Aug 16, 2008 at 8:56 AM
Hi Fernando,

I dont understand what you really mean. The setup i have is that i dont have any trace categories defined in the .config file. This is because i dont want to route anything to a specific tracelistener.
I have a trace listener defined at the "All Events" level which basically catches all events.

So my setup is simply a catch all database tracelistener.

Now looking at the code, i think Logging block somehow knows that a category has already been defined higher up in the heirachy and it adds the log entry for that category as well.
Problem is that it duplicates the actual log entry record, rather than just adding an association in the categorylog table for database trace listener.
Aug 18, 2008 at 9:17 AM
Edited Aug 18, 2008 at 9:27 AM
Errrmmmmmmmm, this was my mistake. I had created a database view to, get the log information along with category names etc. The query was returing extra data and i didnt notice i was viewing the view and not the table. :(

The reason i was getting multiple log entries was because the method


static void AddTracingCategories(LogEntry log,bool replacementDone)

in LogWriter.cs adds the TracingOperation Category to the LogEntry class. This adds an additional record in my CategoryLog table. When my view displays the data, it joins on this link and the log entry record and you see duplicate views.

Is there a way of preventing the TracingOperationCategory from automatically getting added to the LogEntry.Categories collection because i am relating my logentry records by the Activity ID in the database, so i can query all logentries by the ActivityID.


Aug 19, 2008 at 3:22 PM

There's now configuration knob you can twist to avoid this. However, isn't it enough to make the SQL query smarter and flatten the 1-N entry to categories relationship?

Aug 19, 2008 at 7:49 PM
Yeh, that is what i did. The problem was that the AddTracingCategories method as you know is inside the core logging block and i didnt want to touch any of that code. What i did notice was
that the AddTracingCategories method, copied the logentry.categories collection and then Added trace categories into it. Which meant that the first item in the collection would be the original
category added when the logentry instance was created. So in the database trace listener where the CategoryLog recods are inserted, i simply put a break in the foreach loop, to only insert first
record and then break out :). Its doing what i want and maybe in the future , there can be a way of achieving what i need.

So far by using the Logging block, i have ensured that we have an easy interface to log our errors, trace, audit events consitently. Like i mentioned i needed to log extra information and i was able to
do that with relative ease. What it means now is that, we can now trace all critical operations and monitor their performance using the web based logviewer which i will be writing for the project.

Because i am now logging the begin time and end time of each traced operation, i can generate statistics on the perfomance of methods :)

The ActivityID is very useful for ensuring that i group all log entries (I use the new ranking methods in sql server 2005 to reorder the logentries ) and as i am logging the MethodName with every logentry, i can further do a select on the method of interest. So all in all
It was great using the logging block to get the work done in little time.

Thanks for your help Fernando.