Problem:
Client applications are intermitently (once a week) getting timeouts during proxy.Open() and only on that specific method call. The client that got the timeout can call the WCF service a couple of seconds later with no issues.
Setup:
All clients running Windows 7 64-bit, .NET 4.5.1, Microsoft Security Essentials
Server is running Windows Server 2012R2, .NET 4.5.1, no antivirus installed
WCF service is running as a standard windows service:
[ServiceContract(SessionMode = SessionMode.Required)]
[ServiceBehavior(InstanceContextMode = InstanceContextMode.Single, ConcurrencyMode = ConcurrencyMode.Multiple)]
Total number of clients = 30. At most 3 are accessing the WCF service simulataniously. A client talks with the service through many different methods (synchronizing different tables), but the session lasts at most 20 seconds. Every message sent is guaranteed to be less than 2MB in size.
proxy is a System.ServiceModel.ClientBase, which was created via Visual Studio - Add service reference.
app.config
server side:
<system.serviceModel>
<services>
<service behaviorConfiguration="secureBehavior" name="MyService.SynchronizationService">
<endpoint address="net.tcp://localhost:8999/MyService/SynchronizationService" binding="netTcpBinding" bindingConfiguration="secureNetTcp" contract="MyService.ISynchronizationService">
<identity>
<certificateReference storeName="Root" storeLocation="LocalMachine" x509FindType="FindByThumbprint" findValue="..." />
</identity>
</endpoint>
</service>
</services>
<bindings>
<netTcpBinding>
<binding name="secureNetTcp" openTimeout="00:00:25" closeTimeout="00:00:19" receiveTimeout="00:10:10" sendTimeout="00:01:00"
listenBacklog="100" maxConnections="100" maxBufferPoolSize="20971520" maxBufferSize="2097152" maxReceivedMessageSize="2097152">
<reliableSession ordered="true" inactivityTimeout="00:10:00" enabled="true"/>
<readerQuotas maxArrayLength="2147483647" maxBytesPerRead="2147483647" maxDepth="2147483647" maxNameTableCharCount="2147483647" maxStringContentLength="2147483647" />
<security mode="TransportWithMessageCredential">
<transport clientCredentialType="Windows" protectionLevel="EncryptAndSign" />
<message clientCredentialType="Windows" algorithmSuite="Basic256Sha256" />
</security>
</binding>
</netTcpBinding>
</bindings>
<behaviors>
<serviceBehaviors>
<behavior name="secureBehavior">
<serviceMetadata httpGetEnabled="false" httpsGetEnabled="false" />
<serviceCredentials>
<serviceCertificate findValue="..." storeLocation="LocalMachine" storeName="Root" x509FindType="FindByThumbprint" />
</serviceCredentials>
<serviceThrottling maxConcurrentCalls="100" maxConcurrentSessions="100" maxConcurrentInstances="100" />
</behavior>
</serviceBehaviors>
</behaviors>
</system.serviceModel>
client side:
<system.serviceModel>
<bindings>
<netTcpBinding>
<binding name="NetTcpBinding_ISynchronizationService" openTimeout="00:00:25" closeTimeout="00:00:19" receiveTimeout="00:01:00" sendTimeout="00:04:00"
listenBacklog="100" maxConnections="100" maxBufferPoolSize="20971520" maxBufferSize="2097152" maxReceivedMessageSize="2097152">
<reliableSession ordered="true" inactivityTimeout="00:10:00" enabled="true"/>
<readerQuotas maxArrayLength="2147483647" maxBytesPerRead="2147483647" maxDepth="2147483647" maxNameTableCharCount="2147483647" maxStringContentLength="2147483647" />
<security mode="TransportWithMessageCredential">
<transport clientCredentialType="Windows" protectionLevel="EncryptAndSign"/>
<message clientCredentialType="Windows" algorithmSuite="Basic256Sha256"/>
</security>
</binding>
</netTcpBinding>
</bindings>
<client>
<endpoint address="net.tcp://bla.foo.com:8999/MyService/SynchronizationService" binding="netTcpBinding"
bindingConfiguration="NetTcpBinding_ISynchronizationService" contract="MyService.ISynchronizationService" name="NetTcpBinding_ISynchronizationService" />
</client>
</system.serviceModel>
Error messages at client side:
Two types of error messages are thrown:
1)
System.TimeoutException: Client is unable to finish the security negotiation within the configured timeout (00:00:00). The current negotiation leg is 1 (00:00:00).
---> System.TimeoutException: The open operation did not complete within the allotted timeout of 00:00:00. The time allotted to this operation may have been a portion of a longer timeout.
---> System.TimeoutException: Open timed out after 00:00:00 while establishing a transport session to net.tcp://bla.foo.com:8999/MyService/SynchronizationService. The time allotted to this operation may have been a portion of a longer timeout.
---> System.TimeoutException: Connecting to via net.tcp://bla.foo.com:8999/MyService/SynchronizationService timed out after 00:00:00. Connection attempts were made to 0 of 1 available addresses (). Check the RemoteAddress of your channel and verify that the DNS records for this endpoint correspond to valid IP Addresses. The time allotted to this operation may have been a portion of a longer timeout.
2)
System.TimeoutException: The open operation did not complete within the allotted timeout of 00:00:00. The time allotted to this operation may have been a portion of a longer timeout.
---> System.TimeoutException: Open timed out after 00:00:00 while establishing a transport session to net.tcp://bla.foo.com:8999/MyService/SynchronizationService. The time allotted to this operation may have been a portion of a longer timeout.
---> System.TimeoutException: Connecting to via net.tcp://bla.foo.com:8999/MyService/SynchronizationService timed out after 00:00:00. Connection attempts were made to 0 of 1 available addresses (). Check the RemoteAddress of your channel and verify that the DNS records for this endpoint correspond to valid IP Addresses. The time allotted to this operation may have been a portion of a longer timeout.
Debugging steps:
At first I figured this was a problem on the client side. Perhaps the Internet connection hadn't come up after waking from sleep or something like that. So I added checks into the client code to check for network connection, ping www.intel.com and www.amd.com, wait 10 seconds before calling WCF service, etc. But this didn't help.
Then I added a check into the client code, to actually open a socket to the WCF service manually. Point blank verify that a connection exists. I also verified that I'm not using the using pattern with the proxy, only try { } finally { } with proper Abort() and Close() calls. Yet still the clients sometimes timeout even after verifying the connection (I do close the verification socket properly before calling the WCF service).
Both the client and server Event Viewer is clean of any errors or warnings during when the timeout happened. Server and client load is non-existent, pretty much idle the entire time.
Since the timeout only happens during the Open() method call and even on a client that is in the same local network as the server, I'm thinking thist must be a server side issue.
Tracing:
My final step was to enable tracing on the server side and see what is going on. Unfortunately this doesn't provide much insight. At the moment of the timeout, I can see that my socket verification succeeds, but then no more messages or activity.
One might think that this is a clear sign of no Internet connection or packets getting dropped. But then why does the problem only ever happen during the Open() method call and even inside the local network? It can't be a hardware issue either, because the WCF service used to be on a different server, running Server 2008R2, with the exact same issues.
Help:
Are there any WCF gurus out there that can help me track down this problem?
Could this be a WCF internal bug of some kind, not handling sockets correctly?
For instance, tracing showed me that even after a client has properly finished talking with the WCF service - called a method with [IsTerminating=true] attribute and called proxy.Close() - WCF still throws an exception internally. Depending where you look at in trace log there are different messages:
1) Activity = receive bytes on connection; Error thrown = System.TimeoutException - The socket was aborted because an asynchronous receive from the socket did not complete within the allotted timeout of 00:02:00. The time allotted to this operation may have been a portion of a longer timeout.
2) Activity = 0000000000000; Error thrown = System.Net.Sockets.SocketException - An existing connection was forcibly closed by the remote host.
3) Activity = 0000000000000; Error thrown = System.Net.Sockets.SocketException - The I/O operation has been aborted because of either a thread exit or an application request.
4) Activity = 0000000000000; Error thrown = System.ServiceModel.CommunicationException - The socket connection was aborted. This could be caused by an error processing your message or a receive timeout being exceeded by the remote host, or an underlying network resource issue. Local socket timeout was '00:02:00'.
Bonus points for anyone who can help get rid of those internal errors as well (these occur after the client has finished talking to the server). Currently I'm thinking that one has to use reflection to go inside the bowl of WCF, find the socket used and close it manually...
Edit:
Bonus points to me :) I found how to fix the internal SocketExceptions at the server side, every time a client closes - How to properly close a client proxy (An existing connection was forcibly closed by the remote host)?
Now I need to test if this has any effect on the Open() timeouts. I probably won't be able to push out a new version of the client until new year... In the mean time, if anyone has ideas about the Open() timeouts, please do share.
