WCF: Troubleshooting Socket Abort Error

[アーティクル]
08/16/2012

WCF: Troubleshooting Socket Abort Error

============================================================================================================================================================

Scenario 1:

Client: Console application

Server: WCF service

Same machine: Yes

Step 1:

Search for “Exception” keyword, start from bottom

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Receive()

System.Net.Sockets Error: 0 : [6488] Exception in the Socket#37659220::Receive - An existing connection was forcibly closed by the remote host

System.Net.Sockets Verbose: 0 : [6488] Exiting Socket#37659220::Receive() -> 0#0

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Dispose()

System.Net Error: 0 : [6488] Exception in the HttpWebRequest#22213592:: - The underlying connection was closed: An unexpected error occurred on a receive.

System.Net Error: 0 : [6488] Exception in the HttpWebRequest#22213592::EndGetResponse - The underlying connection was closed: An unexpected error occurred on a receive.

Step 2:

Observe the socket ID, used here.

Thread: 6488

Socket: 37659220, Unique socket number to move further.

Receiving a Re-set: 0#0

Step 3:

Search this unique socket number up, till we get the constructor.

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Socket(InterNetwork#2) <-- SOCKET GETS CREATED , using Network card 2

System.Net.Sockets Verbose: 0 : [6488] Exiting Socket#37659220::Socket()

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Connect(100:80#1678115162)

System.Net.Sockets Verbose: 0 : [6488] Exiting Socket#37659220::Connect()

System.Net Information: 0 : [6488] Associating HttpWebRequest#22213592 with ConnectStream#3388666

System.Net Information: 0 : [6488 ] HttpWebRequest#22213592 - Request: POST //_vti_bin/MyLists.asmx HTTP/1.1 <-- We can see that, HttpWebRequest is using the socket and the request looks bit odd with (“//”)

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Send()

System.Net.Sockets Verbose: 0 : [6488] Data from Socket#37659220::Send

System.Net.Sockets Verbose: 0 : [6488] 00000000 : 50 4F 53 54 20 2F 2F 5F-76 74 69 5F 62 69 6E 2F : POST //_vti_bin/ <-- We are sending the POST request to server

System.Net.Sockets Verbose: 0 : [6488] 00000010 : 4C 69 73 74 73 2E 61 73-6D 78 20 48 54 54 50 2F : MyLists.asmx HTTP/

System.Net.Sockets Verbose: 0 : [6488] 00000020 : 31 2E 31 0D 0A 55 73 65-72 2D 41 67 65 6E 74 3A : 1.1..User-Agent:

System.Net.Sockets Verbose: 0 : [6488] 00000030 : 20 4D 6F 7A 69 6C 6C 61-2F 34 2E 30 20 28 63 6F : Mozilla/4.0 (co

System.Net.Sockets Verbose: 0 : [6488] 00000040 : 6D 70 61 74 69 62 6C 65-3B 20 4D 53 49 45 20 36 : mpatible; MSIE 6

System.Net.Sockets Verbose: 0 : [6488] 00000050 : 2E 30 3B 20 4D 53 20 57-65 62 20 53 65 72 76 69 : .0; MS Web Servi

System.Net.Sockets Verbose: 0 : [6488] 00000060 : 63 65 73 20 43 6C 69 65-6E 74 20 50 72 6F 74 6F : ces Client Proto

System.Net.Sockets Verbose: 0 : [6488] 00000070 : 63 6F 6C 20 32 2E 30 2E-35 30 37 32 37 2E 33 36 : col 2.0.50727.36

System.Net.Sockets Verbose: 0 : [6488] 00000080 : 33 34 29 0D 0A 43 6F 6E-74 65 6E 74 2D 54 79 70 : 34)..Content-Typ

System.Net.Sockets Verbose: 0 : [6488] 00000090 : 65 3A 20 74 65 78 74 2F-78 6D 6C 3B 20 63 68 61 : e: text/xml; cha

System.Net.Sockets Verbose: 0 : [6488] 000000A0 : 72 73 65 74 3D 75 74 66-2D 38 0D 0A 53 4F 41 50 : rset=utf-8..SOAP

System.Net.Sockets Verbose: 0 : [6488] 000000B0 : 41 63 74 69 6F 6E 3A 20-22 68 74 74 70 3A 2F 2F : Action: "

System.Net.Sockets Verbose: 0 : [6488] 000000C0 : 73 63 68 65 6D 61 73 2E-6D 69 63 72 6F 73 6F 66 : schemas.microsof

System.Net.Sockets Verbose: 0 : [6488] 000000D0 : 74 2E 63 6F 6D 2F 73 68-61 72 65 70 6F 69 6E 74 : t.com/sharepoint

System.Net.Sockets Verbose: 0 : [6488] 000000E0 : 2F 73 6F 61 70 2F 47 65-74 4C 69 73 74 22 0D 0A : /soap/GetList"..

System.Net.Sockets Verbose: 0 : [6488] 000000F0 : 41 75 74 68 6F 72 69 7A-61 74 69 6F 6E 3A 20 4E : Authorization: N <-- Sending the NTLM ticket

System.Net.Sockets Verbose: 0 : [6488] 00000100 : 54 4C 4D 20 54 6C 52 4D-54 56 4E 54 55 41 41 42 : TLM TlRMTVNTUAAB

System.Net.Sockets Verbose: 0 : [6488] 00000110 : 41 41 41 41 74 37 49 49-34 67 51 41 42 41 41 79 : AAAAt7II4gQABAAy

System.Net.Sockets Verbose: 0 : [6488] 00000120 : 41 41 41 41 43 67 41 4B-41 43 67 41 41 41 41 46 : AAAACgAKACgAAAAF

System.Net.Sockets Verbose: 0 : [6488] 00000130 : 41 73 34 4F 41 41 41 41-44 30 4E 45 4D 54 41 77 : As4OAAAAD0NEMTAw

System.Net.Sockets Verbose: 0 : [6488] 00000140 : 4D 53 31 58 4D 44 6C 44-54 31 4A 51 0D 0A 48 6F : MS1XMDlDT1JQ..Ho

System.Net.Sockets Verbose: 0 : [6488] 00000150 : 73 74 3A 20 63 64 31 30-30 31 2D 77 30 39 0D 0A : st: cd1001-w09..

System.Net.Sockets Verbose: 0 : [6488] 00000160 : 43 6F 6E 74 65 6E 74 2D-4C 65 6E 67 74 68 3A 20 : Content-Length:

System.Net.Sockets Verbose: 0 : [6488] 00000170 : 30 0D 0A 0D 0A : 0....

System.Net.Sockets Verbose: 0 : [6488] Exiting Socket#37659220::Send() -> 373#373 <-- Packet size: 373 byte

System.Net Information: 0 : [6488] ConnectStream#3388666 - Sending headers

{

User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; MS Web Services Client Protocol 2.0.50727.3634)

Content-Type: text/xml; charset=utf-8

SOAPAction: "schemas.microsoft.com/sharepoint/soap/GetList"

Authorization: NTLM TlRMTVNTUAABAAAAt7II4gQABAAyAAAACgAKACgAAAAFAs4OAAAAD0NEMTAwMS1XMDlDT1JQ

Host: cd1001-w09

Content-Length: 0

System.Net Verbose: 0 : [6488] Data from ConnectStream#3388666::ResubmitWrite

System.Net Verbose: 0 : [6488] 00000000 : 3C 3F 78 6D 6C 20 76 65-72 73 69 6F 6E 3D 22 31 : <?xml version="1

System.Net Verbose: 0 : [6488] 00000010 : 2E 30 22 20 65 6E 63 6F-64 69 6E 67 3D 22 75 74 : .0" encoding="ut

System.Net Verbose: 0 : [6488] 00000020 : 66 2D 38 22 3F 3E 3C 73-6F 61 70 3A 45 6E 76 65 : f-8"?><soap:Enve

System.Net Verbose: 0 : [6488] 00000030 : 6C 6F 70 65 20 78 6D 6C-6E 73 3A 73 6F 61 70 3D : lope xmlns:soap=

System.Net Verbose: 0 : [6488] 00000040 : 22 68 74 74 70 3A 2F 2F-73 63 68 65 6D 61 73 2E : "schemas.

System.Net Verbose: 0 : [6488] 00000050 : 78 6D 6C 73 6F 61 70 2E-6F 72 67 2F 73 6F 61 70 : xmlsoap.org/soap

System.Net Verbose: 0 : [6488] 00000060 : 2F 65 6E 76 65 6C 6F 70-65 2F 22 20 78 6D 6C 6E : /envelope/" xmln

System.Net Verbose: 0 : [6488] 00000070 : 73 3A 78 73 69 3D 22 68-74 74 70 3A 2F 2F 77 77 : s:xsi="ww

System.Net Verbose: 0 : [6488] 00000080 : 77 2E 77 33 2E 6F 72 67-2F 32 30 30 31 2F 58 4D : w.w3.org/2001/XM

System.Net Verbose: 0 : [6488] 00000090 : 4C 53 63 68 65 6D 61 2D-69 6E 73 74 61 6E 63 65 : LSchema-instance

System.Net Verbose: 0 : [6488] 000000A0 : 22 20 78 6D 6C 6E 73 3A-78 73 64 3D 22 68 74 74 : " xmlns:xsd="htt

System.Net Verbose: 0 : [6488] 000000B0 : 70 3A 2F 2F 77 77 77 2E-77 33 2E 6F 72 67 2F 32 : p://www.w3.org/2

System.Net Verbose: 0 : [6488] 000000C0 : 30 30 31 2F 58 4D 4C 53-63 68 65 6D 61 22 3E 3C : 001/XMLSchema"><

System.Net Verbose: 0 : [6488] 000000D0 : 73 6F 61 70 3A 42 6F 64-79 3E 3C 47 65 74 4C 69 : soap:Body><GetLi <-- SOAP envelope

System.Net Verbose: 0 : [6488] 000000E0 : 73 74 20 78 6D 6C 6E 73-3D 22 68 74 74 70 3A 2F : st xmlns="http:/

System.Net Verbose: 0 : [6488] 000000F0 : 2F 73 63 68 65 6D 61 73-2E 6D 69 63 72 6F 73 6F : /schemas.microso

System.Net Verbose: 0 : [6488] 00000100 : 66 74 2E 63 6F 6D 2F 73-68 61 72 65 70 6F 69 6E : ft.com/sharepoin

System.Net Verbose: 0 : [6488] 00000110 : 74 2F 73 6F 61 70 2F 22-3E 3C 6C 69 73 74 4E 61 : t/soap/"><listNa

System.Net Verbose: 0 : [6488] 00000120 : 6D 65 3E 73 74 61 6E 74-65 63 2E 63 6F 6D 20 69 : me>stantec.com i

System.Net Verbose: 0 : [6488] 00000130 : 6D 61 67 65 73 32 3C 2F-6C 69 73 74 4E 61 6D 65 : mages2</listName

System.Net Verbose: 0 : [6488] 00000140 : 3E 3C 2F 47 65 74 4C 69-73 74 3E 3C 2F 73 6F 61 : ></GetList> </soa

System.Net Verbose: 0 : [6488] 00000150 : 70 3A 42 6F 64 79 3E 3C-2F 73 6F 61 70 3A 45 6E : p:Body></soap:En

System.Net Verbose: 0 : [6488] 00000160 : 76 65 6C 6F 70 65 3E : velope>

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Receive()

System.Net.Sockets Error: 0 : [6488] Exception in the Socket#37659220::Receive - An existing connection was forcibly closed by the remote host <-- We receive the socket abort as soon as we send request,

System.Net.Sockets Verbose: 0 : [6488] Exiting Socket#37659220::Receive() -> 0#0 <-- 0#0, indicates the socket reset.

System.Net.Sockets Verbose: 0 : [6488] Socket#37659220::Dispose()

System.Net Error: 0 : [6488] Exception in the HttpWebRequest#22213592:: - The underlying connection was closed: An unexpected error occurred on a receive.

System.Net Error: 0 : [6488] Exception in the HttpWebRequest#22213592::EndGetResponse - The underlying connection was closed: An unexpected error occurred on a receive.

Step 4:

Let us check how the HttpRequestobject (containing bad URL is initialized) : 22213592

Searching it in upward direction, till we get the constructor.

System.Net Verbose: 0 : [6488] HttpWebRequest#22213592::HttpWebRequest(<xyz.com//_vti_bin/MyLists.asmx#1404855713>)

Resolution:

Correct the code where we initialize the URI (<xyz.com//_vti_bin/MyLists.asmx#1404855713>)
Once this URI is corrected, we may still see the reset being sent after some request being getting executed.
So, who is sending these aborts ?
Since the communication is limited to same machine, probably some anti-virus running on same box may issue reset.
We disabled the anti-virus and issue was resolved.

=================================================================================================================================================================

Scenario 2:

WCF Service: Azure Box (IIS)

.Net App: local box

Unable to send the large stream request to server, small stream works fine.

Large stream results in Socket aborts …

Step 1: Review client side - system.net

System.Net.Sockets Verbose: 0 : [6204] Socket#49520539::Receive()

DateTime=2012-07-31T20:31:49.1575346Z

System.Net.Sockets Error: 0 : [6204] Exception in the Socket#49520539::Receive - An existing connection was forcibly closed by the remote host

DateTime=2012-07-31T20:35:40.6306796Z

System.Net.Sockets Verbose: 0 : [6204] Exiting Socket#49520539::Receive() -> 0#0

DateTime=2012-07-31T20:35:40.6306796Z

System.Net.Sockets Verbose: 0 : [6204] Socket#49520539::Dispose()

DateTime=2012-07-31T20:35:40.6366802Z

System.Net Error: 0 : [6204] Exception in the HttpWebRequest#41480906:: - The underlying connection was closed: An unexpected error occurred on a receive.

DateTime=2012-07-31T20:35:40.6366802Z

System.Net Error: 0 : [6204] Exception in the HttpWebRequest#41480906::GetResponse - The underlying connection was closed: An unexpected error occurred on a receive.

DateTime=2012-07-31T20:35:40.6366802Z

Looks like we received the Connection reset "0#0" on socket (49520539)

Step 2: More on socket

Socket creation:

System.Net.Sockets Verbose: 0 : [6204] Socket#49520539::Socket(InterNetwork#2)

System.Net Information: 0 : [6204] Connection#27162691 - Created connection from 191.161.41.21:64777 to 61.51.8.71:80.

DateTime=2012-07-31T20:31:30.3526543Z

System.Net Information: 0 : [6204] Associating HttpWebRequest#21818579 with ConnectStream#65311427

DateTime=2012-07-31T20:31:30.3526543Z

System.Net Information: 0 : [6204] HttpWebRequest#21818579 - Request: POST /Service1.svc HTTP/1.1

Content-Type: text/xml; charset=utf-8

SOAPAction: "tempuri.org/IService1/FindMySQLCommand"

Host: www.mydatasynccloud.com

Transfer-Encoding: chunked

Expect: 100-continue

Accept-Encoding: gzip, deflate

Connection: Keep-Alive

System.Net Verbose: 0 : [6204] WebRequest::Create(<www.mydatasynccloud.com/Service1.svc>)

DateTime=2012-07-31T20:31:17.6963888Z

System.Net Verbose: 0 : [6204] HttpWebRequest#21818579::HttpWebRequest(<www.mydatasynccloud.com/Service1.svc#-980531855>)

DateTime=2012-07-31T20:31:17.7053897Z

191.161.41.21:64777: Client box IP

61.51.8.71:80: Server IP address

So a stream connection was made on this socket and finally we received a reset from the server.

But why ?

Un-able to understand, why we receiving the connection reset ...

Step 3: Other parts ..

Server side - system.net traces

Can’t find any exception here.....

Reviewed the WCf traces, no luck ...

Note:

The reason we won’t be able to find anything in system.Net traces of server is because of the fact that the on azure box, WCF service is hosted on IIS which will use the Http.Sys module and not the system.Net module.

Getting Netmon traces

On client side: Conversation.ProcessName == "ClientWindowsService.exe"

Last Ack received from server (4:50:58):

Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-26-B9-46-31-D2],SourceAddress:[00-26-F2-00-1C-52]

Ipv4: Src = 61.51.8.71, Dest = 191.161.41.21, Next Protocol = TCP, Packet ID = 54380, Total IP Length = 40

Tcp: Flags=...A...., SrcPort=HTTP(80), DstPort=50219, PayloadLen=0, Seq=2109676365, Ack=2615881813, Win=510 (scale factor 0x8) = 130560

After this Ack, the client waits for server to finish processing the request for almost three mins, and then it receives a reset (4:54:32).

Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-26-B9-46-31-D2],SourceAddress:[00-26-F2-00-1C-52]

Ipv4: Src = 61.51.8.71, Dest = 191.161.41.21, Next Protocol = TCP, Packet ID = 7133, Total IP Length = 40

Tcp: Flags=.....R.., SrcPort=HTTP(80), DstPort=50219, PayloadLen=0, Seq=2109676365, Ack=0, Win=0 (scale factor 0x8) = 0

So did server issued this reset ?

For client app,

61.51.8.71 IP address with this SourceAddress:[00-26-F2-00-1C-52], sends the reset.

As per cx, 61.51.8.71: is Windows Azure box (so for client clearly server issued the reset, but why ?)

And is it actually the server issuing the reset or someone else ?

On server side: tcp.Port ==50219

Server sending last Ack (4:51:00)

Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[02-F5-0A-1C-FF-0D],SourceAddress:[00-15-5D-32-2D-CE]

Ipv4: Src = 11.21.181.51, Dest = 71.41.161.31, Next Protocol = TCP, Packet ID = 6597, Total IP Length = 40

Tcp: Flags=...A...., SrcPort=HTTP(80), DstPort=50219, PayloadLen=0, Seq=2109676365, Ack=2615881813, Win=510 (scale factor 0x8) = 130560

Server received a reset from some intermediate device (4:54:33):

Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-15-5D-32-2D-CE],SourceAddress:[00-25-B4-CD-14-80]

Ipv4: Src = 71.41.161.31, Dest = 11.21.181.51, Next Protocol = TCP, Packet ID = 16839, Total IP Length = 40

Tcp: Flags=.....R.., SrcPort=50219, DstPort=HTTP(80), PayloadLen=0, Seq=2615881813, Ack=0, Win=0 (scale factor 0x8) = 0

For WCF Service,

Machine (71.41.161.31) whose Mac address is “SourceAddress:[00-25-B4-CD-14-80]” is sending a reset.

So clearly there is some intermediate device (Machine (71.41.161.31) whose Mac address is “SourceAddress:[00-25-B4-CD-14-80]” ) who sent the reset to server after a magic number of 3 minute.

And then finally server sent the reset to client box.

We know that the server may take more than 3 min to send the response since we are since a big stream request.

So we have following possible solutions:

Possible solutions:

===================

a) increase the NLB/device idle connection timout value to more than 3:30 minutes

b) or sending dummy tcp/ip traffic to avoid connection idle

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters\KeepAliveInterval DWORD : value 3000(decimal).

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters\KeepAliveTime DWORD: value 3000(decimal).

Restart the machine and test the client again.

msdn.microsoft.com/en-us/library/system.net.servicepointmanager.settcpkeepalive.aspx

System.Net.ServicePointManager.SetTcpKeepAlive(true, 20000, 20000); //20 seconds

or do this:

msdn.microsoft.com/en-us/library/system.net.servicepointmanager.settcpkeepalive.aspx

public static void SetTcpKeepAlive(

bool enabled,

int keepAliveTime,

int keepAliveInterval

)

Adding the above line on client side before creating the WCF proxy object fixed the issue.

This is just the starting, I will try to get more scenerios to finally win over the socket abort errors.

次の方法で共有

WCF: Troubleshooting Socket Abort Error

その他のリソース