XMLTraceListener - CallStack EventViewer

Topics: General discussion, Logging Application Block
Apr 16, 2009 at 12:01 AM
We have WCF and Enterprise Library tracing both logging to an XMLTraceListener.  The XMLTraceListener does a great job and we are using Service Trace Viewer to view our logs.   The XMLTraceListener is configured to  write the call stack to our svclog files as well.  All is working fine.

However, if the  XMLTraceListener is configured to write the call stack, it seams we are unable to get the call stack to show up in the EventViewer!

I realize you can NOT configure the Event Viewer to display the call stack.  We put the call stack in the LogEntry extended property.  This works fine as long as the XMLTraceListener is not configured to log the call stack.

Has anyone seen this behavior or have ideas as to why we are?



Apr 16, 2009 at 3:53 AM
Are you sure the stack trace is not included in the log in the event viewer?  And could you elaborate more about how are you forwarding the logs to the event viewer? You said you use the xmltracelistener so logs are being sent in an xml file.  When do you perform logging in the event viewer?


Sarah Urmeneta
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Apr 16, 2009 at 10:03 PM
OK we've simplified it even more.  We have a category called Trace.  The Trace Category has two trace listeners
 
1. XML Trace Listener
2. Formatted Even Log Trace Listener
 
Problem: The XMLTraceListener prevents Log Entries that have information in their Extended Properties from being displayed in the Event Viewer.
 
Reproduction:
 
1. Some of our log entries we need to log the call stack, for others we do not.  When we do want to log the call stack we put it the Log Entry’s in this standard way:
 
Dictionary<string, object> dictionary = new Dictionary<string, object>();
DebugInformationProvider informationHelper = new DebugInformationProvider();
informationHelper.PopulateDictionary(dictionary);
logentry.ExtendedProperties = dictionary;
 
All log entries, including those with call stack information are displayed in the Event Viewer.
 
2. Then we add the XMLTraceListener (TraceOutputOptions set to none)
 
With the XMLTraceListner in place, Log Entries that have call stack information are no longer displayed in the Event Viewer
 
Ugh..
 
How is the order in which the trace listeners execute specified? 
 
Thanks
Jess
 
Apr 17, 2009 at 4:27 AM
Hi,

I tried your repro steps but no luck. I still see the call stack on both Event viewer and the xml trace. can you post your config or better send us your sample repro project.

Valiant Dudan
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Apr 17, 2009 at 4:06 PM
OK, here are exact steps to reproduce the problem - it a beauty.  It appears to be tied to changing the TraceOuputOptions and order matters.

Set Up: We have a "diagnostics" button that fires several traces, some traces have call stack in the extended properties some that do not

Scenario 1: EventLogTraceViewer Alone (confirm number of events to EventViewer when working, we have 20)
Step 1: Modify configuration file so Trace Category only has an EventLogTraceListener
Step 2: Press diagnostic button emitting a mix of traces, some with the call stack in extended properties some with out
EventViewer: Confirm there are 20 events in the Event Viewer
XMLLOG: Confirm there are no traces in the XML file (as one would expect)

Scenario 2: Add an XMLTraceListener- EventViewer fine, XML Log file has problems
Step 4: Modify configuration file adding an XMLTraceListener with TraceOutputOptions  set to CallStack
Step 5: Rebuild application (ensure no caching)
Step 6: Press diagnostic button again
EventViewer: Confirm there are 20 events in the Event Viewer (fine)
XMLLOG: bug 1The ONLY traces that show up in the XML log file are those that do NOT have the call stack in the extended properties

Scenario 3: Change TraceOutputOption Value - Event Viewer problems, log file same problems
Step 7: Modify configuration file changing the XMLTraceListener TraceOutputOptions set to None
Step 8: Rebuild application (ensure no caching)
Step 9: Press diagnostic button again
EventViewer: bug 2 only 16 events in the Event Viewer!
XMLLOG: bug 1, the ONLY traces that show up in the XML log file are those that do NOT have the call stack in the extended properties

Scenario 4: Getting it working again
At this point, you can change the value of TraceOutputOptions all day long and you won't get 20 events in the Event Viewer
Step 10: Remove the XMLTraceListener, save the conf file
Step 11: Add the XMLTraceListener back, set it's TraceOutputOptions to CallStack, rebuild
Step 12: Press diagnostic button again
EventViewer: Confirm there are 20 events in the Event Viewer
XMLLOG: bug 1The ONLY traces that show up in the XML log file are those that do NOT have the call stack in the extended properties


So:  Two problems

bug 1 Logs where we have put the call stack into its extended properties are not showing up in the XML log file when viewed with Service Trace Viewer

bug 2 Changing the TraceOutpuOption value  in the XML Trace Listener is stops logs with extended property values from showing up in the Event Viewer


This looks like a lot of steps but takes about 5 minutes to confirm. On our end it has taken 2 days to distill this problem down so we appreciate your help.   This is a huge enterprize application so providing a repro app is not so easy. 

Thanks Jess






Apr 20, 2009 at 8:53 AM
Hi Jess, the order in which the tracelisteners are executed depends on the order you defined them in the config.  In your initial post, my understanding was the logs were all there except that the StackTrace is not included in the log information.  After reading your succeeding posts,  my understanding now is that log entries are not being logged if they they have the call stack in their extended properties.  Could you verify if we could generally say that logs are not being logged if it has extended properties (by putting any dummy info in your dictionary)?  I was unable to repro both bugs you're referring to that's why I need you to verify this for me.   Do you have the same calls to Logger.Write?


Sarah Urmeneta
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Apr 21, 2009 at 7:31 PM
As we worked on determining the exact steps to reproduce this we learned more.  We initially thought it was just the stack trace, but we now realize, as outlined in the last post, that:

1. Log entries (that have call stack info in the dictionary) are not getting logged to Service Trace Viewer

2. Following the exact steps above, when changing the TraceOutpuOption value  in the XML Trace Listener, logs with extended property values do not get logged to the The Event Viewer

both execute through the same call to Logger.Write()

Trying to  be clear:

Are you saying you have a test application that writes Log Entries that have the call stack in their extended properties to a log file using an XML Trace Listener?  And these log entries are visible in Service Trace Viewer?

This is part of a huge enterprise application so I can't really extract the project to send you. 






Apr 22, 2009 at 4:59 AM
Yes, I have a test application with xml trace listener.  I didn't exactly put the call stack infomation, I just put some dummy info in it.  I was able to view the logs in the Service Trace Viewer.  
Does the fact that you put the call stack info in the dictionary relevant?  Or could we say that if you put any info in the extended properties would repro the case?

I understand why you can't send the project but could you repro it in just a sample project? 


Sarah Urmeneta
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Apr 22, 2009 at 6:49 PM
Would you mind putting the call stack in your  sample app, as you know these are lines to do so (below).  I don't know if the actual content, meaning the fact that it is a call stack, makes a difference - but it is a large amount of data, which may stress things more than just a short string would.

If we can't get it to repoduce in your sample app - I don't know if mine will be much better (smile) but I can give it a shot.  But would you mind just adding the call stack to your app, perhaps we will get lucky.

Dictionary<string, object> dictionary = new Dictionary<string, object>();
DebugInformationProvider informationHelper = new DebugInformationProvider();
informationHelper.PopulateDictionary(dictionary);
logentry.ExtendedProperties = dictionary;

Apr 22, 2009 at 7:41 PM

OK - I commented out the code that puts the call stack in the extended properties but continue to put the user name and method name as shown below.

All works fine - when I uncomment the code to load the call stack into the extended properties the logs disapear.

So I think it does have something specific to do with the call stack.  Can you try repoducing the exact steps I provided above, including putting the call stack in the extended properties as shown below?

Thanks
Jess

// with these lines commented out works fine
//Dictionary<string, object> dictionary = new Dictionary<string, object>();
//DebugInformationProvider informationHelper = new DebugInformationProvider();
//informationHelper.PopulateDictionary(dictionary);
//logentry.ExtendedProperties = dictionary;

string Key = "User Name";

 

 

if (logentry.ExtendedProperties.ContainsKey(Key))

 

{

logentry.ExtendedProperties[Key] = GetUserName();

}

 

else

 

 

 

{

 

logentry.ExtendedProperties.Add(Key, GetUserName());

}

 

// Setup the Calling Method.

 

 

 

Key = "Calling Method";

 

 

if (logentry.ExtendedProperties.ContainsKey(Key))

 

{

logentry.ExtendedProperties[Key] = GetCallingMethod(logInfo.CallingTrace);

}

 

else

 

 

 

{

 

logentry.ExtendedProperties.Add(Key, GetCallingMethod(logInfo.CallingTrace));

}

 

Logger.Write(logentry);

 

Apr 23, 2009 at 7:27 AM
Hi,

I tried reproducing it using the steps that you've provided. But I still got log on both EventLog and XML. Commenting out the said lines will log the assigned values to the extended properties on both EventLog and XML. Uncommeting it would result to the call stack and the added to the extended properties on both EventLog and XML. 

Valiant Dudan
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
Apr 23, 2009 at 1:47 PM
OK, given we have a huge enterprise application here and it's hard for me to extract it, why don't you send me your repro app and I will work with that here to see if I can reproduce the problem?

Thanks
Jess
Apr 27, 2009 at 6:44 PM
so um, how about sending your sample application?
Apr 28, 2009 at 5:30 AM
Where should we send it then?


Sarah Urmeneta
Global Technology & Solutions
Avanade, Inc.
entlib.support@avanade.com
May 12, 2009 at 4:47 PM

jpratt@arrowstreetcapital.com would be great