WCF service startup too slow? Have you thought to CRL check?
A customer of mine was experiencing an annoying delay when calling a WCF service hosted in IIS6. He provided the following elements with the issue description:
"The delay only occurs when calling the WCF service the first time. The following calls were executed in a reasonable time. It was enough to restart the client application to reproduce the delay on the first call."
"As many assembly references the service includes, the longer the time spent to execute the first call."
To be honest the customer solution was rather complex, including several WCF services calling each other, and Sharepoint as well, but this is not fundamental to our purpose.
When looking at the WCF traces, I couldn't notice any meaningful delay: looked like the service started receiving network data after the delay was spent.
The client appeared stuck during wait on service reply. What was happening?
I thought to ask for network traces on the server, and suddenly noticed something interesting: there were several DNS requests to a host named "crl.microsoft.com". In that case the DNS request kept failing, I guess that had been increasing the delay. I filtered traffic on HTTP and DNS protocols, and found something like that:
1: 1275 66.940689 {HTTP:35, TCP:34, IPv4:33} 10.15.0.2 10.15.2.64 HTTP HTTP: Request, POST /NetSourcingServices/UserManagementService.svc
2: 1277 67.056225 {HTTP:35, TCP:34, IPv4:33} 10.15.2.64 10.15.0.2 HTTP HTTP: Response, HTTP/1.1, Status Code = 100
3: 1278 67.056580 {HTTP:35, TCP:34, IPv4:33} 10.15.0.2 10.15.2.64 HTTP HTTP: HTTP Payload
4: 1284 67.294377 {DNS:38, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
5: 1295 68.293987 {DNS:40, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
6: 1312 69.293905 {DNS:40, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
7: 1344 71.293828 {DNS:38, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
8: 1345 71.293841 {DNS:40, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
10: 1425 75.293731 {DNS:40, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
11: 1522 79.340669 {DNS:41, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
12: 1537 80.340345 {DNS:42, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
13: 1554 81.340301 {DNS:41, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
14: 1570 82.458183 {DNS:38, UDP:37, IPv4:36} CSDC001 10.15.2.64 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Response - Server failure
15: 1586 83.449603 {DNS:42, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
16: 1587 83.449618 {DNS:41, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
17: 1598 84.160484 {DNS:40, UDP:39, IPv4:19} CSDC002 10.15.2.64 DNS DNS: QueryId = 0xB1D2, QUERY (Standard query), Response - Server failure
18: 1651 87.152577 {DNS:42, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
19: 1652 87.152592 {DNS:41, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
20: 1728 91.777601 {DNS:46, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
21: 1746 92.777358 {DNS:47, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
22: 1780 93.777342 {DNS:46, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
23: 1815 95.159803 {DNS:41, UDP:39, IPv4:19} CSDC002 10.15.2.64 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Response - Server failure
24: 1818 95.457228 {DNS:42, UDP:37, IPv4:36} CSDC001 10.15.2.64 DNS DNS: QueryId = 0x5AD3, QUERY (Standard query), Response - Server failure
25: 1832 96.449083 {DNS:47, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
26: 1833 96.449096 {DNS:46, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
27: 1894 100.448957 {DNS:47, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
28: 1895 100.448970 {DNS:46, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
29: 1972 104.511458 {DNS:48, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
30: 2003 105.511227 {DNS:49, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
31: 2042 106.511190 {DNS:48, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
32: 2070 107.159070 {DNS:46, UDP:39, IPv4:19} CSDC002 10.15.2.64 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Response - Server failure
33: 2086 108.456693 {DNS:47, UDP:37, IPv4:36} CSDC001 10.15.2.64 DNS DNS: QueryId = 0xC575, QUERY (Standard query), Response - Server failure
34: 2105 109.448570 {DNS:49, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
35: 2106 109.448584 {DNS:48, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
36: 2210 113.448417 {DNS:49, UDP:37, IPv4:36} 10.15.2.64 CSDC001 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
37: 2211 113.448431 {DNS:48, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0xA60E, QUERY (Standard query), Query for crl.microsoft.com of type Host Addr on class Internet
38: 2337 118.079858 {DNS:68, UDP:39, IPv4:19} 10.15.2.64 CSDC002 DNS DNS: QueryId = 0x4B05, QUERY (Standard query), Query for cssqlvs01.csf.lan of type Host Addr on class Internet
39: 2338 118.080052 {DNS:68, UDP:39, IPv4:19} CSDC002 10.15.2.64 DNS DNS: QueryId = 0x4B05, QUERY (Standard query), Response - Success
40: 2397 118.268103 {HTTP:35, TCP:34, IPv4:33} 10.15.2.64 10.15.0.2 HTTP HTTP: Response, HTTP/1.1, Status Code = 200
The customer declared the delay was a bit more than 50 seconds: please have a look at the time between the POST and the response.. are you able to notice anything?
There are about 50 seconds between them, and a lot of DNS queries in the middle.
What is crl.microsoft.com? The CRL acronym stands for "Certificate Revocation List". The Certificate Revocation List (CRL) is a document maintained and published by a certification authority (CA) that lists certificates issued by the CA that are no longer valid. Each signed assembly was checked against the CRL before being loaded and, as you can see in the network traces, because of the network configuration the DNS wasn't able to resolve "crl.microsoft.com".
Please have a look at this article: https://support.microsoft.com/default.aspx/kb/936707 (FIX: A .NET Framework 2.0 managed application that has an Authenticode signature takes longer than usual to start): "When you start a Microsoft .NET Framework 2.0 managed application that has a Microsoft Authenticode signature, the .NET Framework 2.0 managed application takes longer than usual to start."; "This problem occurs because a .NET Framework 2.0 managed assembly that has an Authenticode signature takes longer than usual to load. The signature is always verified when the .NET Framework 2.0 managed assembly that has an Authenticode signature is loaded."
Since you’re using .NET 3.*, you could simply add the entry below to both the application config files:
2: <configuration>
3: <runtime>
4: <generatePublisherEvidence enabled="false"/>
5: </runtime>
6: </configuration>
7:
So if you observe a strange delay during your application start up, just check if you're trying to load Authenticode signed assembly in your application, and introduce the configuration entry above as a double check.
Cheers,
Andrea