Tuesday, January 29, 2008

Logging EntityBag's SOAP Request and Response Messages

Windows Communication Framework's WCF Service Configuration Editor lets you log SOAP request and response messages, as well as specify WCF service and client configuration declaratively. Newly created WCF services that use the HTTP transport specify the wsHttp binding, which applies SOAP message-level security with data encryption, digital signatures, and enables other WS-* security features.

WCF's service configuration is specified by the <system.serviceModel> section of the service project's Web.config (or App.config) file. Following are default service configuration values of Danny Sullivan's sample C# EntityBagSample.sln project from the NorthwindService.csproj project's Web.config file:

<system.serviceModel>
  <services>
    <service name="NorthwindService.Service1"
     behaviorConfiguration="NorthwindService.Service1Behavior">
      <!-- Service Endpoints -->
      <endpoint address="" binding="wsHttpBinding" contract="NorthwindService.IService1"
       bindingConfiguration="wsHttp">
        <!-- 
            Upon deployment, the following identity element should be removed or replaced to reflect
            the identity under which the deployed service runs.  If removed, WCF will infer an 
            appropriate identity automatically.
        -->
        <identity>
          <dns value="localhost"/>
        </identity>
      </endpoint>
      <endpoint address="mex" binding="mexHttpBinding" contract="IMetadataExchange"/>
    </service>
  </services>

  <bindings>
    <wsHttpBinding>
      <binding name="wsHttp" maxReceivedMessageSize ="50000000" maxBufferPoolSize="50000000" >
      </binding>
    </wsHttpBinding>
  </bindings>

  <behaviors>
    <serviceBehaviors>
      <behavior name="NorthwindService.Service1Behavior">
        <!-- To avoid disclosing metadata information, set the value below to false and remove 
             the metadata endpoint above before deployment -->
        <serviceMetadata httpGetEnabled="true"/>
        <!-- To receive exception details in faults for debugging purposes, set the value below 
             to true.  Set to false before deployment to avoid disclosing exception information -->
        <serviceDebug includeExceptionDetailInFaults="true"/>
      </behavior>
    </serviceBehaviors>
  </behaviors>
</system.serviceModel>

The basicHttp binding provides no message- or transport-level security by default, which enables comparing performance and message transport size of insecure and secure services.

Note: If you don't want to change the security model, go to step 5 to enable message logging.

It's a relatively simple process to change the transport by the following steps:

1. Open EntityBagSample.sln and choose Tools, WCF Configuration Editor, choose File, Open and navigate to and open the ...\entitybag\NorthwindService\Web.config file, and expand Services and Bindings nodes.

2. Click the Bindings node and the New Binding Configuration link to open the binding page. Type basicHttp as the Name and change the MaxBufferPoolSize, MaxBufferSize, and MaxReceivedMessageSize values to very large number, such as 50000000.

3. Click the top Endpoints node to open its Service EndPoint page, change its Name to NwBasicHttp or the like and select basicHttpBinding from the Binding dropdown list.

4. Open the BindingConfiguration list and choose the basicHttp configuration you created in step 2.

5. Click the Diagnostics node and click the Message Logging section's Enable Message Logging Link to turn Message Logging on and create an  ...\entitybag\NorthwindService\Web_messages.svclog file. Optionally, click the Enable Log Auto Flush link to allow reading the log file while the service is running.

6. Click the Diagnostics node's Message Logging item to display the Message Logging page, set the LogEntireMessage and LogMessagesAtServiceLevel properties to True and increase the value of MaxSizeOfMessageToLog to a very large number.

 

7. Choose File, Save to save your changes. NorthwindService's Web.config file's <system.serviceModel> section now appears as shown here (changes are set bold):

<system.serviceModel>
  <diagnostics>
    <messageLogging logEntireMessage="true" logMalformedMessages="true"
      logMessagesAtServiceLevel="true" logMessagesAtTransportLevel="true"
      maxSizeOfMessageToLog="50000000" />
  </diagnostics>
  <services>
    <service behaviorConfiguration="NorthwindService.Service1Behavior"
      name="NorthwindService.Service1">
      <endpoint address="" binding="basicHttpBinding" bindingConfiguration="basicHttp"
        name="NwBasicHttpEP" contract="NorthwindService.IService1">
        <identity>
          <dns value="localhost" />
        </identity>
      </endpoint>
      <endpoint address="mex" binding="mexHttpBinding" name="NwMexEP"
        contract="IMetadataExchange" />
    </service>
  </services>

  <bindings>
    <basicHttpBinding>
      <binding name="basicHttp" maxBufferSize="50000000" maxBufferPoolSize="50000000"
        maxReceivedMessageSize="50000000" />
    </basicHttpBinding>
    <wsHttpBinding>
      <binding name="wsHttp" maxBufferPoolSize="50000000" maxReceivedMessageSize="50000000" />
    </wsHttpBinding>
  </bindings>

  <behaviors>
    <serviceBehaviors>
      <behavior name="NorthwindService.Service1Behavior">
        <!-- To avoid disclosing metadata information, set the value below to false 
             and remove the metadata endpoint above before deployment -->
        <serviceMetadata httpGetEnabled="true"/>
        <!-- To receive exception details in faults for debugging purposes, set the 
             value below to true.  Set to false before deployment to avoid 
             disclosing exception information -->
        <serviceDebug includeExceptionDetailInFaults="true"/>
      </behavior>
    </serviceBehaviors>
  </behaviors>
</system.serviceModel>

8. You must match the TestApp.csproj client project binding with that of the service, so choose File, Open and navigate to and open ...\entitybag\TestApp\App.config. Repeat step 2 for the Client node and step 3, except change the Endpoint name to basicHttpBinding_IService1.

 

9. Choose File, Save to save your changes. The TestApp's App.Config file's <system.serviceModel> section now appears as shown here (changes are set bold):

<configuration>
  <system.serviceModel>
    <bindings>
      <basicHttpBinding>
        <binding name="basicHttp" maxBufferSize="50000" maxBufferPoolSize="50000"
          maxReceivedMessageSize="50000" />
      </basicHttpBinding>
      <wsHttpBinding>
        <binding name="WSHttpBinding_IService1" closeTimeout="00:01:00"
          openTimeout="00:01:00" receiveTimeout="00:10:00" sendTimeout="00:01:00"
          bypassProxyOnLocal="false" transactionFlow="false" hostNameComparisonMode="StrongWildcard"
          maxBufferPoolSize="5000000" maxReceivedMessageSize="5000000"
          messageEncoding="Text" textEncoding="utf-8" useDefaultWebProxy="true"
          allowCookies="false">
          <readerQuotas maxDepth="32" maxStringContentLength="8192" maxArrayLength="50000000"
            maxBytesPerRead="4096" maxNameTableCharCount="16384" />
          <reliableSession ordered="true" inactivityTimeout="00:10:00"
            enabled="false" />
          <security mode="Message">
            <transport clientCredentialType="Windows" proxyCredentialType="None"
              realm="" />
            <message clientCredentialType="Windows" negotiateServiceCredential="true"
              algorithmSuite="Default" establishSecurityContext="true" />
          </security>
        </binding>
      </wsHttpBinding>
    </bindings>
    <client>
      <endpoint address="http://localhost:56475/Service1.svc" binding="basicHttpBinding"
        bindingConfiguration="basicHttp" contract="ServiceReference1.IService1"
        name="basicHttpBinding_IService1">
        <identity>
          <dns value="localhost" />
        </identity>
      </endpoint>
    </client>
  </system.serviceModel>

10. You must associate files with the *.svclog extension with ServiceModel Trace Viewer tool (SvcTraceViewer.exe), so navigate to and right-click ...\entitybag\NorthwindService\Web_messages.svclog, choose Open With, click Browse, navigate to and double-click \Program Files\Microsoft SDKs\Windows\v6.0A\Bin\SvcTraceViewer.exe, and set it as the default program for opening .svclog files.

11. Run EntityBagSample.sln a couple of times to generate trace files, and then double click Web_messages.svclog to open the Trace Viewer. Click the Activity item to load the main pane, and then select a message. Here's the screen capture of a GetCustomerAndOrders SOAP request message:

Click screen capture to open a full-size image.

Click here to open the full request message in IE (1.2 kB).

12. Click the next message after a request message to review the SOAP response message to the GetCustomerAndOrders request, which includes the ContextSnapshot, shown here:

Click screen capture to open a full-size image.

Notice the 4-second delay between completion of the request and response messages. This delay is the reason that I downgraded the message-level security to basicHttp. I wanted to determine if encryption, signing, and other security overhead was responsible for what I considered to be a slow response time. It wasn't. Stay tuned for future posts on EntityBag performance.

Click here to open the full response message in IE (20 kB).

Updated January 30, 2008: Fixed response message's full-size image link and added comment on response time.

2 comments:

Hardy said...

Is there a way I can configure the logging to have a separated log file every hour?

Roger Jennings (--rj) said...

@Hardy,

I don't know of any configuration settings that would generate a new set of log files every hour.