WCF Service Trace Viewer Part 2

Thursday, June 9, 2011

Continuing from the previous part, now we’ll have a look at what happens when we call the service using WSHttpBinding. For this, I have to instantiate my LearnWcfService service passing the WSHttp binding endpoint to the constructor. The rest of the method runs the exact same instructions as before. I have also changed the instantiateData attribute in the app.config file to ClientLogWsHttp.svclog, just to keep the log files separate.

Clearly, there are more activities than the ‘basic’ version. As done before, I click on the Construct ChannelFactory… activity and the Get ChannelEndpointElement trace and see that we’re now binding through wsHttpBinding.

In addition to other things, we see an activity called ‘Set up Secure Session’. This is where a secure session information is instantiated. The next few activities – Processing message 1, 2, 3 are all related to this hand-shake.

We’ll see some details on this even on the Message tab.

Just to compare, scroll up and compare the number of messages on Basic Http binding 8 : 22. I think we can account so much of data-exchange and bandwidth usage as the price paid for security. Here’s what I learned about those messages:

RST – Request Secure Token
RSTR – Request Secure Token Response
SCT – Secure Context Token

Looking at the first message, you’ll find the full ‘xml’ised version of the request that is being sent.

        1: <E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">

       2:     <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">

       3:         <EventID>0</EventID>

       4:         <Type>3</Type>

       5:         <SubType Name="Information">0</SubType>

       6:         <Level>8</Level>

       7:         <TimeCreated SystemTime="2011-04-12T05:09:50.1644952Z" />

       8:         <Source Name="System.ServiceModel.MessageLogging" />

       9:         <Correlation ActivityID="{4e5dfe15-fb15-4097-bf66-5f1a28f85d74}" />

        <Execution ProcessName="ClientApplication" ProcessID="7208" ThreadID="1" />

        <Channel />

        <Computer>MyComputer</Computer>

    </System>

    <ApplicationData>

        <TraceData>

            <DataItem>

                <MessageLogTraceRecord Time="2011-04-12T10:39:50.1584946+05:30" Source="ServiceLevelSendRequest" Type="System.ServiceModel.Channels.BodyWriterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">

                    <s:Envelope xmlns:a="http://www.w3.org/2005/08/addressing" xmlns:s="http://www.w3.org/2003/05/soap-envelope">

                        <s:Header>

                            <a:Action s:mustUnderstand="1">http://tempuri.org/ILearnWcfService/AddInt</a:Action>

                            <a:MessageID>urn:uuid:438598db-0d89-4e42-a955-11e9be43088f</a:MessageID>

                            <a:ReplyTo>

                                <a:Address>http://www.w3.org/2005/08/addressing/anonymous</a:Address>

                            </a:ReplyTo>

                        </s:Header>

                        <s:Body>

                            <AddInt xmlns="http://tempuri.org/">

                                <arg1>1</arg1>

                                <arg2>2</arg2>

                            </AddInt>

                        </s:Body>

                    </s:Envelope>

                </MessageLogTraceRecord>

            </DataItem>

        </TraceData>

    </ApplicationData>

</E2ETraceEvent>

Notice the arguments and the method call that is being mentioned in the xml. Also see the Source attribute that says ServiceLevelSendRequest. But if you continue looking at the next message for AddInt, you’ll find that the request has now been fully encrypted and totally unreadable (CipherValue element). The message is now in the TransportSend status. This is WSHttpBinding at work.

The very next message (first of the AddIntResponse message) is the TransportReceive stage where the data is still encrypted and it is only in the last of the AddIntResponse messages does it come the ServiceLevelReceiveReply stage where it becomes readable. We see how WSHttp secures the data during the different layers. If you cross check, the data remains as plain- readable-text throughout the process of Basic Http binding.

       1: <E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">

       2:     <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">

       3:         <EventID>0</EventID>

       4:         <Type>3</Type>

       5:         <SubType Name="Information">0</SubType>

       6:         <Level>8</Level>

       7:         <TimeCreated SystemTime="2011-04-12T05:10:11.9866772Z" />

       8:         <Source Name="System.ServiceModel.MessageLogging" />

       9:         <Correlation ActivityID="{c4060ea9-a788-4490-b228-03dd04f6de28}" />

        <Execution ProcessName="ClientApplication" ProcessID="7208" ThreadID="1" />

        <Channel />

        <Computer>MyComputer</Computer>

    </System>

    <ApplicationData>

        <TraceData>

            <DataItem>

                <MessageLogTraceRecord Time="2011-04-12T10:40:11.9856771+05:30" Source="ServiceLevelReceiveReply" Type="System.ServiceModel.Security.SecurityVerifiedMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">

                    <HttpResponse>

                        <StatusCode>OK</StatusCode>

                        <StatusDescription>OK</StatusDescription>

                        <WebHeaders>

                            <Connection>Close</Connection>

                            <Content-Length>5094</Content-Length>

                            <Cache-Control>private</Cache-Control>

                            <Content-Type>application/soap+xml; charset=utf-8</Content-Type>

                            <Date>Tue, 12 Apr 2011 05:10:11 GMT</Date>

                            <Server>ASP.NET Development Server/10.0.0.0</Server>

                            <X-AspNet-Version>4.0.30319</X-AspNet-Version>

                        </WebHeaders>

                    </HttpResponse>

                    <s:Envelope xmlns:s="http://www.w3.org/2003/05/soap-envelope">

                        <s:Header>

                            <a:Action s:mustUnderstand="1" u:Id="_2" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:a="http://www.w3.org/2005/08/addressing">http://tempuri.org/ILearnWcfService/AddIntResponse</a:Action>

                            <a:RelatesTo u:Id="_3" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:a="http://www.w3.org/2005/08/addressing">urn:uuid:438598db-0d89-4e42-a955-11e9be43088f</a:RelatesTo>

                            <o:Security s:mustUnderstand="1" xmlns:o="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd">

                                <u:Timestamp u:Id="uuid-5d226149-f6d5-4f95-bf27-63a2be952b57-11" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">

                                    <u:Created>2011-04-12T05:10:11.964Z</u:Created>

                                    <u:Expires>2011-04-12T05:15:11.964Z</u:Expires>

                                </u:Timestamp>

                                <c:DerivedKeyToken u:Id="uuid-5d226149-f6d5-4f95-bf27-63a2be952b57-7" xmlns:c="http://schemas.xmlsoap.org/ws/2005/02/sc" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">

                                    <o:SecurityTokenReference>

                                        <o:Reference URI="urn:uuid:c10f0ecb-1c3e-4afe-b6f3-240d19318329" ValueType="http://schemas.xmlsoap.org/ws/2005/02/sc/sct"></o:Reference>

                                    </o:SecurityTokenReference>

                                    <c:Offset>0</c:Offset>

                                    <c:Length>24</c:Length>

                                    <c:Nonce>

                                        <!-- Removed-->

                                    </c:Nonce>

                                </c:DerivedKeyToken>

                                <c:DerivedKeyToken u:Id="uuid-5d226149-f6d5-4f95-bf27-63a2be952b57-8" xmlns:c="http://schemas.xmlsoap.org/ws/2005/02/sc" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">

                                    <o:SecurityTokenReference>

                                        <o:Reference URI="urn:uuid:c10f0ecb-1c3e-4afe-b6f3-240d19318329" ValueType="http://schemas.xmlsoap.org/ws/2005/02/sc/sct"></o:Reference>

                                    </o:SecurityTokenReference>

                                    <c:Nonce>

                                        <!-- Removed-->

                                    </c:Nonce>

                                </c:DerivedKeyToken>

                                <e:ReferenceList xmlns:e="http://www.w3.org/2001/04/xmlenc#">

                                    <e:DataReference URI="#_1"></e:DataReference>

                                    <e:DataReference URI="#_4"></e:DataReference>

                                </e:ReferenceList>

                                <Signature xmlns="http://www.w3.org/2000/09/xmldsig#">

                                    <SignedInfo>

                                        <CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></CanonicalizationMethod>

                                        <SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#hmac-sha1"></SignatureMethod>

                                        <Reference URI="#_0">

                                            <Transforms>

                                                <Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></Transform>

                                            </Transforms>

                                            <DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"></DigestMethod>

                                            <DigestValue>iXK6QpgkLD0hNgV4zbd2p8UZTMk=</DigestValue>

                                        </Reference>

                                        <Reference URI="#_2">

                                            <Transforms>

                                                <Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></Transform>

                                            </Transforms>

                                            <DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"></DigestMethod>

                                            <DigestValue>dd5TBRTJOCia0ttk9jZrsX/BIwY=</DigestValue>

                                        </Reference>

                                        <Reference URI="#_3">

                                            <Transforms>

                                                <Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></Transform>

                                            </Transforms>

                                            <DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"></DigestMethod>

                                            <DigestValue>wUCHZwK/oA2Zf1DW7teWcpC60DE=</DigestValue>

                                        </Reference>

                                        <Reference URI="#uuid-5d226149-f6d5-4f95-bf27-63a2be952b57-11">

                                            <Transforms>

                                                <Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></Transform>

                                            </Transforms>

                                            <DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"></DigestMethod>

                                            <DigestValue>UdX3NPo64fNoC7c5BTaTu45ORvY=</DigestValue>

                                        </Reference>

                                    </SignedInfo>

                                    <SignatureValue>9i+ypgIBP6F6GCs81fikfS/Sly8=</SignatureValue>

                                    <KeyInfo>

                                        <o:SecurityTokenReference xmlns:o="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd">

                                            <o:Reference ValueType="http://schemas.xmlsoap.org/ws/2005/02/sc/dk" URI="#uuid-5d226149-f6d5-4f95-bf27-63a2be952b57-7"></o:Reference>

                                        </o:SecurityTokenReference>

                                    </KeyInfo>

                                </Signature>

                            </o:Security>

                        </s:Header>

                        <s:Body u:Id="_0" xmlns:u="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">

                            <AddIntResponse xmlns="http://tempuri.org/">

                                <AddIntResult>3</AddIntResult>

                            </AddIntResponse>

                        </s:Body>

                    </s:Envelope>

                </MessageLogTraceRecord>

            </DataItem>

        </TraceData>

    </ApplicationData>

</E2ETraceEvent>

Once again, the same process repeats for the AddDouble operation.

.SvcLog files used for the article
References:
http://msdn.microsoft.com/en-us/library/aa751795.aspx – Using Service Trace Viewer
http://msdn.microsoft.com/en-us/library/ms733025.aspx – Configuring Tracing
http://msdn.microsoft.com/en-us/library/ms732023.aspx – Service Trace Viewer Tool
http://msdn.microsoft.com/en-us/library/ms751526.aspx – Tracing and Message Logging

i have one query.

if you check your = > image_thumb7_5822844A.png

then you'll find => Add Double method twice and if you check

the log then first request loks encrypted and second loks plain request. so i am new to this...can you eleborate more on that...why first is encrypted and second request is plain...?

Ashish Patel - Friday, November 16, 2012 5:32:33 AM

@@Ashish,

The argument is the same for the AddDouble calls as well. The first one is when we receive it from the TransportReceive stage and the second one is from the ServiceLevelReceiveReply stage where it becomes readable.

Arun

Arun Mahendrakar - Monday, November 19, 2012 3:16:13 AM

2 Comments