I have a C# Windows application running as "NT AUTHORITY\Network Service" that needs to make a POST request over HTTPS to server hosted on Apache Tomcat. I'm using HttpWebRequest to issue the request. I'm accepting the server certificate by setting a ServicePointManager.ServerCertificateValidationCallback delegate. There is a long delay (~ 15 seconds) between the call to HttpWebRequest.GetRequestStream() and invocation of the ServerCertificateValidationCallback callback.
When I run the same code as LocalSystem, it works fine without the delay. What could be going wrong?
Things I've tried so far:
========================================================================
None of this seems to work. There's still a consistent delay of 15 seconds in HttpWebRequest.GetRequestStream(). Also collected System.Net traces.
Code:
ServicePointManager.ServerCertificateValidationCallback = new RemoteCertificateValidationCallback(ValidateRemoteCertificate);
ServicePointManager.Expect100Continue = false;
ServicePointManager.CheckCertificateRevocationList = false;
public static bool ValidateRemoteCertificate( object sender, X509Certificate certificate, X509Chain chain, SslPolicyErrors policyErrors)
{
Trace.TraceInformation("HttpWebClient.ValidateRemoteCertificate: Implicitly allowing SSL certificate");
return true;
}
Web client:
HttpWebRequest request = (HttpWebRequest) HttpWebRequest.Create(uri);
request.KeepAlive = false;
request.ProtocolVersion = HttpVersion.Version11;
request.Method = "POST";
request.Proxy = null;
request.AuthenticationLevel = AuthenticationLevel.None;
request.AllowWriteStreamBuffering = false;
request.ServicePoint.Expect100Continue = false;
byte[] postBytes = Encoding.ASCII.GetBytes(post_data);
request.ContentType = "application/x-www-form-urlencoded";
request.ContentLength = postBytes.Length;
try
{
Stream requestStream = request.GetRequestStream();
Trace.TraceInformation("HttpWebClient.SendRequest Sending request of length {0}...", postBytes.Length);
requestStream.Write(postBytes, 0, postBytes.Length);
Trace.TraceInformation("HttpWebClient.SendRequest Request sent");
requestStream.Close();
}
catch (Exception e)
{
Trace.TraceInformation("HttpWebClient.sendRequest: exception {0}, {1}", e.Message, e.StackTrace);
}
Trace.TraceInformation("HttpWebClient.SendRequest Fetching HTTP response...");
HttpWebResponse response;
response = (HttpWebResponse)request.GetResponse();
System.net Traces: From the traces, the 15 sec delay is from 2011-09-07T21:42:16.7796885Z to 2011-09-07T21:42:31.7897095Z. The errors reported are: Remote certificate has errors:, Certificate name mismatch., A certificate chain processed, but terminated in a root certificate which is not trusted by the trust provider.
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000000 : 14 03 01 00 01
> : .....
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 5#5
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000005 : 01
> : .
> DateTime=2011-09-07T21:42:16.7596885Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 1#1
> DateTime=2011-09-07T21:42:16.7596885Z System.Net Information: 0 :
> [0412] InitializeSecurityContext(credential =
> System.Net.SafeFreeCredential_SECURITY, context = 4b0cd8:12d34d0,
> targetName = 172.16.2.142, inFlags = ReplayDetect, SequenceDetect,
> Confidentiality, AllocateMemory, InitManualCredValidation)
> DateTime=2011-09-07T21:42:16.7596885Z System.Net Information: 0 :
> [0412] InitializeSecurityContext(In-Buffers count=2, Out-Buffer
> length=0, returned code=ContinueNeeded).
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000000 : 16 03 01 00 30
> : ....0
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 5#5
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000005 : A6 50 8C D0 69 C7 46 E5-AB AA B7 D9 02 08 DF E7
> : .P..i.F.........
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000015 : C1 49 0C 98 6C 2F 4C 06-3E 3C 00 ED D2 09 70 56
> : .I..l/L.><....pV
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] 00000025 : AB 4A E0 E8 5F B0 04 0D-3C 97 41 CE A1 B2 89 26
> : .J.._...<.A....&
> DateTime=2011-09-07T21:42:16.7696885Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 48#48
> DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 :
> [0412] InitializeSecurityContext(credential =
> System.Net.SafeFreeCredential_SECURITY, context = 4b0cd8:12d34d0,
> targetName = 172.16.2.142, inFlags = ReplayDetect, SequenceDetect,
> Confidentiality, AllocateMemory, InitManualCredValidation)
> DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 :
> [0412] InitializeSecurityContext(In-Buffers count=2, Out-Buffer
> length=0, returned code=OK).
> DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 :
> [0412] Remote certificate: [Version] V3
>
> [Subject] CN=company Desktop Server, OU=company Desktops, O=company
> Inc., L=city, S=California, C=US Simple Name: company Desktop Server
> DNS Name: company Desktop Server
>
> [Issuer] CN=company Desktop Server, OU=company Desktops, O=company
> Inc., L=city, S=California, C=US Simple Name: company Desktop Server
> DNS Name: company Desktop Server
>
> [Serial Number] AAAAAAAA
>
> [Not Before] 8/26/2011 9:41:33 PM
>
> [Not After] 9/2/2021 9:41:33 PM
>
> [Thumbprint] 46E130D012348CE5EA5E570CCDA5F872A1111111
>
> [Signature Algorithm] sha1RSA(1.2.840.113549.1.1.5)
>
> [Public Key] Algorithm: RSA Length: 1024 Key Blob: 30 81 89 02
> 81 81 00 85 9b fd 1b fc d3 98 3b 67 1b a0 7f fc 7c 69 f9 11 0e 93 d3
> 9b 06 cc 1e 73 74 ed d2 bc 60 1b 4d 62 c7 96 70 99 7f 59 89 f3 d1 c7
> 28 7a e3 d8 98 90 36 52 b9 99 eb fa 68 4b ea 4c 5d 07 88 75 1a 59 8e
> e0 b0 54 c9 f2 a5 94 47 6a 91 07 83 29 4c 0b fc ef 38 72 08 26 0a ba
> b9 85 0e e6 2e a6 29 8d ca 5b 9b e5 41 a5 66 73 e0 37 34 f0 7a a....
**> **DateTime=2011-09-07T21:42:16.7796885Z System.Net Information: 0 :
> [0412] SecureChannel#46104728 - Remote certificate has errors:
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
> [0412] SecureChannel#46104728 - Certificate name mismatch.
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
> [0412] SecureChannel#46104728 - A certificate chain processed, but
> terminated in a root certificate which is not trusted by the trust
> provider.
>
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
> [0412] SecureChannel#46104728 - Remote certificate was verified as
> valid by the user.****
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Send()
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Send
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000000 : 17 03 01 00 B0 B5 76 03-D9 27 40 8F F8 FE 7E FE
> : ......v..'@...~.
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000010 : 94 09 8B F9 73 2D 0C 3E-F9 34 2C 00 C3 6D 59 63
> : ....s-.>.4,..mYc
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000020 : C0 2E EB 03 BE 4E 7D 41-5C D6 ED 85 E9 9C 06 33
> : .....N}A\......3
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000030 : 72 1A AE 81 BB 86 29 C7-F0 03 F6 66 A6 2C 75 98
> : r.....)....f.,u.
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000040 : D4 3A 74 02 C7 F8 63 DE-23 18 51 95 9C 2C 1A 01
> : .:t...c.#.Q..,..
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000050 : 42 03 36 B6 29 FE 00 B5-83 4A DE E1 F5 34 22 B1
> : B.6.)....J...4".
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000060 : E7 42 0F D8 88 D7 72 CA-9C D1 AC 18 D9 2B 55 39
> : .B....r......+U9
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000070 : 3E 8B A4 A2 2D 8B 10 30-0A 40 D4 08 F7 26 56 7B
> : >...-..0.@...&V{
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000080 : FF 6A CC 60 BB BE 80 6A-1C 0A AE C7 3B 86 85 09
> : .j.`...j....;...
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000090 : FD 92 AA A4 56 91 24 9F-50 7C B5 10 10 7B BA 06
> : ....V.$.P|...{..
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 000000A0 : D0 78 77 6A 2E 00 50 CD-C8 5C 33 06 E6 4A 17 17
> : .xwj..P..\3..J..
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 000000B0 : 93 98 20 EE 41
> : .. .A
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Send() -> 181#181
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
> [0412] ConnectStream#34948909 - Sending headers { Content-Type:
> application/x-www-form-urlencoded Host: 172.16.2.142 Content-Length:
> 38 Connection: Close }.
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] Exiting HttpWebRequest#33574638::GetRequestStream() ->
> ConnectStream#34948909
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] ConnectStream#34948909::Write()
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Send()
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Send
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000000 : 17 03 01 00 40 01 D7 42-04 F0 1C 0A 00 2C 39 70
> : [email protected].....,9p
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000010 : 7F C8 55 03 99 25 66 06-CD 6F 28 6E E7 7B 04 71
> : ..U..%f..o(n.{.q
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000020 : C0 25 EF 63 2B 0D 64 0B-AC C2 05 22 E0 0C 88 2D
> : .%.c+.d...."...-
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000030 : 7A C9 B2 2B C1 32 8B 54-BA F8 6D 4D A2 17 A6 77
> : z..+.2.T..mM...w
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] 00000040 : 38 CB 38 B0 88
> : 8.8..
> DateTime=2011-09-07T21:42:31.7897095Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Send() -> 69#69
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] Data from ConnectStream#34948909::Write
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] 00000000 : 6C 61 75 6E 63 68 52 65-66 3D 30 31 32 33 34 35 :
> launchRef=012345
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] 00000010 : 36 37 38 39 26 74 69 63-6B 65 74 3D 39 38 37 36 :
> 6789&ticket=9876
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] 00000020 : 35 34 33 32 31 30 :
> 543210
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] Exiting ConnectStream#34948909::Write()
> DateTime=2011-09-07T21:42:31.7897095Z System.Net Verbose: 0 :
> [0412] ConnectStream#34948909::Close()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net Verbose: 0 :
> [0412] Exiting ConnectStream#34948909::Close()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net Verbose: 0 :
> [0412] ConnectStream#34948909::Close()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net Verbose: 0 :
> [0412] Exiting ConnectStream#34948909::Close()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net Verbose: 0 :
> [0412] HttpWebRequest#33574638::GetResponse()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:31.7997096Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000000 : 17 03 01 00 90
> : .....
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 5#5
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] Socket#48285313::Receive()
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] Data from Socket#48285313::Receive
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000005 : 80 05 0D 3E 37 E7 28 EB-EC 78 7C BC 20 DB 61 7B
> : ...>7.(..x|. .a{
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000015 : 73 8F 6E 71 A1 D6 B9 EA-04 C9 92 E9 8A 88 71 C6
> : s.nq..........q.
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000025 : 7E DB 72 94 80 08 3F 14-CE 12 CC 5D F5 07 91 D0
> : ~.r...?....]....
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000035 : FB EF 7F 51 57 ED 2D 60-11 11 F8 1C 9C 58 99 E5
> : ...QW.-`.....X..
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000045 : 20 8B 5B 0E 61 3C 55 05-89 75 72 F0 F0 5B 92 88
> : .[.a<U..ur..[..
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000055 : 40 C0 39 92 9B 21 E9 9E-69 A0 A8 53 9D 63 96 A5
> : @.9..!..i..S.c..
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000065 : C9 82 02 68 75 DD 44 E3-D7 90 57 66 3C F0 4E A3
> : ...hu.D...Wf<.N.
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000075 : 6E F9 46 4C 40 EB 6A 74-EF 8E E9 76 4B 78 77 D4
> : [email protected].
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] 00000085 : A1 B1 97 01 BB 90 A9 CB-F7 C5 64 BE 0E 83 B3 6C
> : ..........d....l
> DateTime=2011-09-07T21:42:31.8297096Z System.Net.Sockets Verbose:
> 0 : [0412] Exiting Socket#48285313::Receive() -> 144#144
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Information: 0 :
> [0412] Connection#35191196 - Received status line: Version=1.1,
> StatusCode=200, StatusDescription=OK.
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Information: 0 :
> [0412] Connection#35191196 - Received headers { Connection: close
> Content-Length: 2 Date: Wed, 07 Sep 2011 14:37:30 GMT Server:
> Apache-Coyote/1.1 }.
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Information: 0 :
> [0412] ConnectStream#12289376::ConnectStream(Buffered 2 bytes.)
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Information: 0 :
> [0412] Associating HttpWebRequest#33574638 with ConnectStream#12289376
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Information: 0 :
> [0412] Associating HttpWebRequest#33574638 with
> HttpWebResponse#43495525
> DateTime=2011-09-07T21:42:31.8297096Z System.Net Verbose: 0 :
> [0412] Exiting HttpWebRequest#33574638::GetResponse() ->
> HttpWebResponse#43495525
> DateTime=2011-09-07T21:42:31.8297096Z
Finally found the root cause. Here it is:
During the ssl connection, windows update is invoked to update the Root Certificates. This needs internet connection. If the machine is connected to internet, no delay will be seen. If the machine is not connected to internet, 15 second delay is seen because that is the default timeout value for network retrieval of the updated Root Certificates.
This is as per design and not a bug according to the following KB article from microsoft. http://support.microsoft.com/kb/317541
I encountered a similar issue with a server with no internet access. The solution was to disable automatic root cert updates and lower the timeout for the crl list to one second.
To do this.
Start gpedit.msc -> Local Computer policy -> Computer Configuration -> Administrative Templates -> System -> Internet Communication Management -> Internet Communication Settings -> Turn off automatic root certificate update = Enabled
And
Start gpedit.msc -> Local Computer policy -> Computer Configuration -> Windows Settings -> Security Settings -> Public Key Policy -> Certificate Path Validation Path.
Select tab “Network Retrieval” and enable the “Define these policy settings”. Deselect “Automatic update root….”
And most important set the timeout values to 1.
The delay is visible in the network logs...
DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 :
[0412] InitializeSecurityContext(credential = System.Net.SafeFreeCredential_SECURITY, context = 4b0cd8:12d34d0, targetName = 172.16.2.142, inFlags = ReplayDetect, SequenceDetect, Confidentiality, AllocateMemory, InitManualCredValidation) DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 : [0412] InitializeSecurityContext(In-Buffers count=2, Out-Buffer length=0, returned code=OK). DateTime=2011-09-07T21:42:16.7696885Z System.Net Information: 0 : [0412] Remote certificate: [Version] V3
to this:
DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
[0412] SecureChannel#46104728 - Certificate name mismatch. DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 : [0412] SecureChannel#46104728 - A certificate chain processed, but terminated in a root certificate which is not trusted by the trust provider.
DateTime=2011-09-07T21:42:31.7897095Z System.Net Information: 0 :
[0412] SecureChannel#46104728 - Remote certificate was verified as valid by the user.**
Is it possible that in the NetworkService account, your proxy settings etc are not configured correctly, so Schannel cannot get the certificate revocation list, and do other things (like walking the root cert chain) to validate the certificate fast?
When running as networkservice, do a network sniff using Wireshark. That will show you what is happening. Of course it will be gibberish because of SSL, but you should atleast be able to see plaintext outgoing HTTP requests for the CRL and the root certificates.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With