Thursday, 18 November 2010

WCF service throwing immediate timeout

The problem

I was recently writing automated integration tests against a WCF service using NUnit when out of the blue all the tests failed and kept failing. An examination of the exceptions thrown showed that in each case a CommunicationException was being thrown because of a timeout.

What was most perplexing was that the apparent timeouts were being reported immediately but the client configuration was set to defaults: 

<system.serviceModel>
        <bindings>
            <wsHttpBinding>
                <binding name="WSHttpBinding_EnquirySubmissionService" closeTimeout="00:01:00"
                    openTimeout="00:01:00" receiveTimeout="00:10:00" sendTimeout="00:01:00"
                    bypassProxyOnLocal="false" transactionFlow="false" hostNameComparisonMode="StrongWildcard"
                    maxBufferPoolSize="524288" maxReceivedMessageSize="65536"
                    messageEncoding="Text" textEncoding="utf-8" useDefaultWebProxy="true"
                    allowCookies="false">
                    <!-- snip -->
                </binding>
            </wsHttpBinding>
        </bindings>
        <!-- snip -->
  </system.serviceModel>
</configuration>

The service was using WsHttpBinding and was hosted by IIS over HTTPS. The service was also secured using TransportWithMessageCredential and UserName credentials on the message (i.e. username and password).

 

The solution

Firstly I enabled tracing on the service by modifying the Web.config file to include the following: 

<system.diagnostics> 
    <sources> 
        <source name="System.ServiceModel" switchValue="Information,ActivityTracing" propagateActivity="true"> 
            <listeners> 
                <add name="xml" /> 
            </listeners> 
        </source> 
        <source name="System.ServiceModel.MessageLogging"> 
            <listeners> 
                <add name="xml" /> 
            </listeners> 
        </source> 
    </sources> 
    <sharedListeners> 
        <add initializeData="C:\logs\TracingAndLogging-client.svclog" type="System.Diagnostics.XmlWriterTraceListener" name="xml" /> 
    </sharedListeners> 
    <trace autoflush="true" />
</system.diagnostics>

I then queried the service again to promote a timeout communication exception. I found the trace log contained: 

System.ServiceModel.Security.MessageSecurityException: Message security verification failed. ---&amp;gt; System.ComponentModel.Win32Exception: The event log file is full
at System.Diagnostics.EventLog.InternalWriteEvent(UInt32 eventID, UInt16 category, EventLogEntryType type, String[] strings, Byte[] rawData, String currentMachineName) 
at System.Diagnostics.EventLog.WriteEvent(EventInstance instance, Byte[] data, Object[] values) 
at System.Diagnostics.EventLog.WriteEvent(String source, EventInstance instance, Object[] values) 
at System.ServiceModel.Security.SecurityAuditHelper.WriteEventToApplicationLog(EventInstance instance, Object[] parameters) 
at System.ServiceModel.Security.SecurityAuditHelper.WriteMessageAuthenticationSuccessEvent(AuditLogLocation auditLogLocation, Boolean suppressAuditFailure, Message message, Uri serviceUri, String action, String clientIdentity) 
at System.ServiceModel.Security.SecurityProtocol.OnIncomingMessageVerified(Message verifiedMessage) 
at System.ServiceModel.Security.TransportSecurityProtocol.VerifyIncomingMessageCore(Message&amp;amp; message, TimeSpan timeout) 
at System.ServiceModel.Security.TransportSecurityProtocol.VerifyIncomingMessage(Message&amp;amp; message, TimeSpan timeout)

So, the problem actually was that the event log was full! Having emptied the event log everything started working again.

Thursday, 18 November 2010