Using Ukadc.Diagnostics with existing TraceSources

Home > View Post

This is part 6 in a series introducing the Ukadc.Diagnostics project which is currently hosted on codeplex at www.codeplex.com/UkadcDiagnostics.

What follows has to be one of my favourite 'features' of System.Diagnostics. Because it ships with .NET, System.Diagnostics is the logging framework of choice for Microsoft's Product Groups. Which means we can use Ukadc.Diagnostics to expose all their juicy logging data. Let's start with WCF's System.ServiceModel trace source.

For this example we need a test application that uses WCF. Fortunately, the QuickReferenceExample on codeplex is just such an application, so we'll use that here. In essence though, it's just a matter of adding the System.ServiceModel TraceSource to our configuration:

<source name="System.ServiceModel" switchValue="Information" propagateActivity="true">
    <listeners>
        <add name="sql" />
    </listeners>
</source>

Where the "sql" TraceListener is configured in the sharedListeners section
<sharedListeners>
    <add name="sql"
        initializeData="sqlTraceListenerSettings"
        type="Ukadc.Diagnostics.Listeners.SqlTraceListener, Ukadc.Diagnostics" />
</sharedListeners>
and the sqlTraceListenerSettings are configured in the ukadc.diagnostics section (identical to the example in the Using the SqlTraceListener post):

<ukadc.diagnostics>
    <sqlTraceListeners>
        <sqlTraceListener name="sqlTraceListenerSettings" connectionStringName="log"
            commandText="INSERT INTO LogStore VALUES(@Source, @ActivityId, @ProcessId, @ThreadId, @EventType, @Message, @Timestamp)"
            commandType="Text">
            <parameters>
                <parameter name="@Source" propertyToken="{Source}" />
                <parameter name="@ActivityId" propertyToken="{ActivityId}" />
                <parameter name="@ProcessId" propertyToken="{ProcessId}" />
                <parameter name="@ThreadId" propertyToken="{ThreadId}" />
                <parameter name="@EventType" propertyToken="{EventType}" callToString="true"/>
                <parameter name="@Message" propertyToken="{Message}" />
                <parameter name="@Timestamp" propertyToken="{DateTime}" />
            </parameters>
        </sqlTraceListener>
    </sqlTraceListeners>
</ukadc.diagnostics>

So let's not beat about the bush - here's what the output looks like:

System.ServiceModel via the SqlTraceListener

Notice how we've got a mixture of logging output from the System.ServiceModel TraceSource and from our ReferenceWebApplication. You'll also notice that the output from System.ServiceModel can be pretty verbose so you probably want to keep the source's switchValue to something nice and 'high' like Warning or Error.

Of course, you don't have to have System.ServiceModel and ReferenceWebApplication writing to the same listeners - you could just wire the source to a different TraceListener (or even a different SqlTraceListener).

Tags: Ukadc.Diagnostics System.Diagnostics .NET

Post By Josh Twist

Follow me

10:26
12 May 2008

» Next Post: Delegates and Lambda
« Previous Post: Cracking open Zip files in Silverlight Beta 1

Comments:

Posted by JK @ 19 May 2008 12:46
Hi Josh,

I downloaded your project and changed conn.cfg to have a different connection string however when I execute the program, it still refers to your default connection string. Where does it get that information?? It is not from "conn.cfg" file?

Could you explain please?

Thanks, JK

Posted by Josh @ 20 May 2008 03:15
Hi JK,

The .config files in the Solution Folder are only copied at build time as a Build Event. Therefore you might need to rebuild (or manually copy the files to each project folder) if you've made any changes.

Let me know if this resolves your issue.

Josh

Posted by JK @ 20 May 2008 06:59
Thanks Josh.

After rebuilding the solution, the problem went away. This rises two questions:

1) I thought that the configuration file changes need not result in rebuilding, why do I need to rebuild my solution?

2) Secondly, the following lines from the SysDiag.config file shows me a warning on propagateActivity attribute. Can you show me as how to remove that warning? (i.e., when I hover over "propagateActivity" text, it shows "The 'propagateActivity' attribute not declared.')

<source name="System.ServiceModel" switchValue="Off" propagateActivity="true">
<listeners>
<add name="ignored" type="System.Diagnostics.ConsoleTraceListener" />
</listeners>
</source>

Thanks, JK

Posted by Josh @ 20 May 2008 07:27
Hi JK,

1) This is to do with my 'clever' build activity. The configuration files you are editing are copied to the each web folder after the build. This means if you edit them whilst the application is running you're editing the wrong files :) I realise this might be confusing and I apologise for that.

2) Sadly I'm not aware of a solution to this problem. propagateActivity is an additional attribute that extends the source configuration type for WCF only. Therefore it's not in the Visual Studio schemas which causes a warning. Frustrating but nothing to worry about.

HTH

Josh

Posted by JK @ 20 May 2008 07:35
Thanks Josh for a quick reply.

More observations:

1) In your login.aspx file, the membershipProvider attribute is not set. As a result, it doesn't get into your MyCustomMembershipProvider even though the config file mentions it. Then I changed the login.aspx control to point to MyCustomMembershipProvider, then it gets into ValidateUser code. Probably you can explain this.

2) Secondly, because of propagateActivity showing as a warning in IDE, my output results looks little odd. The WCF layer tracings have different activity ID. Can you shed some light on this?

[3696] b0f55fb1-0aef-4892-b2cb-861cd7332c85|Stop: /default.aspx? - 5/20/2008 2:29:31 PM, Process=3696, Thread=9
[3696] 60df2b10-e66f-4b01-a53c-244f2368d0ca|Stop: /Login.aspx?ReturnUrl=%2fdefault.aspx - 5/20/2008 2:29:32 PM, Process=3696, Thread=9
[3696] 624c032d-7107-426f-8084-584803011d78|Start: ValidateUser - 5/20/2008 2:29:36 PM, Process=3696, Thread=9
[3696] 624c032d-7107-426f-8084-584803011d78|Stop: ValidateUser - 5/20/2008 2:29:36 PM, Process=3696, Thread=9
[3696] 624c032d-7107-426f-8084-584803011d78|Stop: /Login.aspx?ReturnUrl=%2fdefault.aspx - 5/20/2008 2:29:36 PM, Process=3696, Thread=9
[1160] b5bae6de-5607-44a6-8359-639492bc542a|Start: GetProducts - 5/20/2008 2:29:36 PM, Process=1160, Thread=15
[1160] b5bae6de-5607-44a6-8359-639492bc542a|Stop: GetProducts - 5/20/2008 2:29:36 PM, Process=1160, Thread=15
[3696] 523ea981-3981-43d7-aa5c-b14f3bec07b1|Stop: /default.aspx - 5/20/2008 2:29:36 PM, Process=3696, Thread=9

Thanks, JK

Posted by Josh @ 20 May 2008 07:48
1) Hmmm... works on my machine :). By default the login control should look to the configured MembershipProvider if one isn't specified on the control.

2) This doesn't really make any sense. The propagateActivity would change the display of your output - only make sure that the activityId passes the process boundary. What is the output you have pasted? From DebugView?

Posted by JK @ 20 May 2008 07:54
Yes. They are directly from debugView.

Posted by Josh @ 20 May 2008 07:57
Cool. So what do you think is funny about them?

What is your initializeData attribute configured to look like in SysDiag.config for the OutputDebugString listener? My guess is something like this:

[{ProcessId}] {ActivityId}|{EventType}: {Message} - {DateTime}, Process={ProcessId}, Thread={ThreadId}

Posted by JK @ 20 May 2008 08:01
I have no problem with the format of the message. My question is that if you follow the trace messages from the previous post, the activity ID is different from the website project and WCF service project. I thought that the propagateActivity attribute would help to keep the same activity id between website and service layer for that session/user. But they are different in spite of propagateActivity being turned on. Am I missing something here?

Posted by Josh @ 20 May 2008 08:05
Nope - you're absolutely right. I hadn't noticed that. What level do you have the System.ServiceModel source set to in both projects?

Posted by JK @ 20 May 2008 08:10
Josh,

As you described in your writeup, there is a common configuration file sysDiag.config at the solution level, this is what I have in that file.

<source name="System.ServiceModel" switchValue="Off" propagateActivity="true">
<listeners>
<add name="ignored" type="System.Diagnostics.ConsoleTraceListener" />
</listeners>
</source>

Sorry to ask dumb question - do I need add this section to both website and service projects' web.config files?

Thanks.

Posted by Josh @ 20 May 2008 08:13
No, the build event should copy the SysDiag.config file to the service and website projects for you. The web.config in each should reference this file as follows:

<system.diagnostics configSource="SysDiag.config" />

Can you just check inside each folder to make sure these files look as you would expect after the copy (i.e. switchValue="Off" and there is at least one listener configured?)

Posted by JK @ 20 May 2008 08:29
Josh, This is what I have in website's web.config file. As you can see that propagateActivity is copied from Sysdiag.config (I believe!).

<system.diagnostics>
<sources>
<source name="ReferenceServiceApplication" switchValue="All" >
<listeners>
<add name="ServiceModelTraceListener" />
</listeners>
</source>
<source name="System.ServiceModel" switchValue="Off" propagateActivity="true">
<listeners>
<add name="ServiceModelTraceListener" />
</listeners>
</source >
</sources>
<sharedListeners >
<add initializeData="C:\temp\log\server_log.svclog" type="System.Diagnostics.XmlWriterTraceListener, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
name="ServiceModelTraceListener" traceOutputOptions="Timestamp" />
</sharedListeners>
<trace autoflush="true" />
</system.diagnostics>

Comments:

Post a comment: