nettracer

Exchange integration error on HP4120 desktop phones - A CA trust issue

2013-01-18T16:18:15Z

I would like to go through an integration problem between Lync phone edition devices and Exchange 2010 that I worked on a while ago. Since the integration wasn’t working properly, users couldn’t access call logs, recorded voice mails, calendar information etc from their desktop phones (HP4120).

To understand the problem in more details, we asked our customer to collect Exchange side configuration information, phone edition logs from a problem device, network trace from Lync FE server etc.

Note: You can find full details on how to collect and analyze CELog data in the following Microsoft whitepaper:

http://www.microsoft.com/en-us/download/details.aspx?id=15668 Understanding and Troubleshooting Microsoft Exchange Server Integration

Troubleshooting:

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

Note: IP addresses, server names, URLs etc are replaced for privacy purposes

1) Lync phone edition device succeeds to obtain autodiscovery information:

...

0:01:43.203.610 : Raw data 211 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.214 4EC0006:5250012 INFO :: NAutoDiscover::DnsAutodiscoverTask::ParseSoapResponse: InternalEwsUrl is https://casarray.contoso.com/EWS/Exchange.asmx

0:01:43.204.593 : Raw data 212 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.215 4EC0006:5250012 INFO :: NAutoDiscover::DnsAutodiscoverTask::ParseSoapResponse: ExternalEwsUrl is https://autodiscover.contoso.com/EWS/Exchange.asmx

...

2) But the Lync phone edition device fails to access the EWS site with the following error (the same error is seen in all device logs) so the integration error occurs:

0:01:43.840.224 : Raw data 206 (char), UCD_LOG_ERROR: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.850 4EC0006:5250012 ERROR :: WebServices::CSoapTransport::ExecuteSoapOperation: Insecure server. errorCode=12045, status=014C0220, hr=80f10043

0:01:43.840.617 : Raw data 196 (char), UCD_LOG_ERROR: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.851 4EC0006:5250012 ERROR :: WebServices::CSoapTransport::SendSoapRequest: ExecuteSoapOperation failed. status=014C0220, hr=80f10043

0:01:43.840.963 : Raw data 225 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.851 4EC0006:5250012 INFO :: WebServices::WebRequestImpl::ExecuteCommon: after SendSoapRequest. hr=0x80f10043, url=https://casarray.contoso.com/EWS/Exchange.asmx

0:01:43.841.216 : Raw data 191 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.851 4EC0006:5250012 INFO :: WebServices::CSoapTransport::GetHttpHeaderInfoFromHandle: hSoapHandle=014C0220, headerInfo=013E2708

0:01:43.841.548 : Raw data 197 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.852 4EC0006:5250012 INFO :: WebServices::CSoapTransport::GetCredentialsInfoFromHandle: hSoapHandle=014C0220, credentialsInfo=013E2670

0:01:43.842.135 : Raw data 165 (char), UCD_LOG_INFO: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.852 4EC0006:5250012 INFO :: WebServices::CSoapTransportStatus::~CSoapTransportStatus: status=014C0220

0:01:43.842.492 : Raw data 182 (char), UCD_LOG_ERROR: 10/19/2012|14:50:27 Aries: 10/19/2012|14:50:27.853 4EC0006:5250012 ERROR :: WebServices::WebRequestImpl::ExecuteCommon: Could not execute SOAP request. hr=0x80f10043

err 014C0220

# as an HRESULT: Severity: SUCCESS (0), Facility: 0x14c, Code 0x220

# for hex 0x220 / decimal 544 :

SE_AUDITID_IPSEC_AUTH_FAIL_CERT_TRUST msaudite.h

# IKE security association establishment failed because peer

# could not authenticate.

# The certificate trust could not be established.%n

# Peer Identity: %n%1%n

...

err 0x80f10043

...

# (user-to-user)

MIDIERR_NOTREADY mmsystem.h

NMERR_INVALID_PACKET_LENGTH netmon.h

ERROR_BAD_NET_NAME winerror.h

# The network name cannot be found.

LDAP_NOT_ALLOWED_ON_RDN winldap.h

...

So the problem looks like a certificate issue.

=> When I check the certificate assigned to CAS array, I see the following:

AccessRules : {System.Security.AccessControl.CryptoKeyAccessRule, System.Security.AccessControl.CryptoKeyAccessRule}

CertificateDomains : {casarray.contoso.com, cas01.contoso.com}

HasPrivateKey : True

IsSelfSigned : False

Issuer : CN=Issuing-CA for contoso, DC=contoso, DC=com

NotAfter : 8/8/2014 3:36:18 PM

NotBefore : 8/8/2012 3:36:18 PM

PublicKeySize : 1024

RootCAType : Enterprise

SerialNumber : 362763723200000000524

Services : IMAP, POP, IIS

Status : Valid

Subject : CN=casarray.contoso.com

Thumbprint : EF32873628362BDA8326108875301F38504AB

Issuer is Issuing-CA for contoso, DC=contoso, DC=com

=> On the other hand, the CA that issues the Lync frontend certificate is the following: (this is taken from Lync server side network trace)

...

+ Tcp: Flags=...A...., SrcPort=5061, DstPort=50855, PayloadLen=1460, Seq=2076240595 - 2076242055, Ack=1109389286, Win=256 (scale factor 0x8) = 65536

TLSSSLData: Transport Layer Security (TLS) Payload Data

- TLS: TLS Rec Layer-1 HandShake: Server Hello. Certificate.

- TlsRecordLayer: TLS Rec Layer-1 HandShake:

ContentType: HandShake:

+ Version: TLS 1.0

Length: 4380 (0x111C)

- SSLHandshake: SSL HandShake Certificate(0x0B)

HandShakeType: ServerHello(0x02)

Length: 77 (0x4D)

+ ServerHello: 0x1

HandShakeType: Certificate(0x0B)

Length: 3423 (0xD5F)

- Cert: 0x1

CertLength: 3420 (0xD5C)

- Certificates:

CertificateLength: 1574 (0x626)

...

+ Signature: Sha1WithRSAEncryption (1.2.840.113549.1.1.5)

+ Issuer: Issuing CA for contoso,com

+ Validity: From: 09/10/12 10:05:05 UTC To: 09/10/14 10:05:05 UTC

+ Subject: casarray.contoso.com

+ SubjectPublicKeyInfo: RsaEncryption (1.2.840.113549.1.1.1)

+ Tag3:

+ Extensions:

+ SignatureAlgorithm: Sha1WithRSAEncryption (1.2.840.113549.1.1.5)

+ Signature:

Certificates:

=> So the issuers of certificates used by Lync server itself and casarray.contoso.com servers are different CAs:

a) CA that issues Lync FE certificate:

Issuing CA for contoso,com

b) CA that issues CAS array certificate:

Issuing-CA for contoso, DC=contoso, DC=com

Apparently two different CAs with similar names issued Lync FE and Exchange CAS array certificates.

Under normal circumstances, if those two CAs are enterprise CAs, they automatically publish their own CA certificates to AD so the clients can download and use them while verifying the certificate chain. But after some internal research I found out that phone edition devices only trust the same CA that assigned the certificate to Lync FE pool to which phone edition device signs in. (except public certificates listed in http://technet.microsoft.com/en-us/library/gg398270(OCS.14).aspx)

RESULTS:

========

After issuing a new certificate to CAS array from the same enterprise CA (Issuing CA for contoso,com) that issues Lync FE certificate as well, the integration problem was resolved.

Hope this helps you when dealing with similar problems...

Thanks,

Murat

Lync 2010 response group members phones keep ringing even if the remote party hangs up the phone

2013-01-18T15:39:35Z

In this blog post, I’ll be talking about a response group problem where the response group members phones keep ringing even if the user calling from pstn side hangs up the phone. I would like to talk about how I troubleshooted this issue:

We first collected ETL traces and network traces from the mediation server to better understand the problem (actually mediation server and frontend server were running on the same machine). Some more details about the response group:

Response group number: 8900

Response group members: user1@contoso.com / user2@contoso.com / user3@contoso.com / user4@contoso.com / user5@contoso.com

In the S4 ETL trace, we can see that once the call is made to response group number, response group application starts ringing each response group member with 15 seconds intervals while it keeps playing music on hold to the caller:

Since none of the response group members answer, response group application goes through each member in a loop fashion. (actually the exact behavior here is identified by response group charateristics like workflow, routing method etc)

Interestingly, even the user who initiated the call to response group hangs up the phone, the rtp traffic from voip gateway keeps coming towards the mediation server:

98312 2012-11-23 08:59:05.383 0.015 172.16.1.7 172.17.1.100RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x3FF62C47, Seq=19584, Time=964130050

98313 2012-11-23 08:59:05.388 0.004 172.17.1.100172.16.1.7 RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x6ED4D5BE, Seq=33285, Time=1945495369

98320 2012-11-23 08:59:05.403 0.015 172.16.1.7 172.17.1.100RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x3FF62C47, Seq=19585, Time=964130210

98322 2012-11-23 08:59:05.408 0.004 172.17.1.100172.16.1.7 RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x6ED4D5BE, Seq=33286, Time=1945495529

98323 2012-11-23 08:59:05.423 0.015 172.16.1.7 172.17.1.100RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x3FF62C47, Seq=19586, Time=964130370

98324 2012-11-23 08:59:05.428 0.004 172.17.1.100172.16.1.7 RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x6ED4D5BE, Seq=33287, Time=1945495689

98326 2012-11-23 08:59:05.443 0.015 172.16.1.7 172.17.1.100RTP 214 PT=ITU-T G.711 PCMA, SSRC=0x3FF62C47, Seq=19587, Time=964130530

So we should have got a SIP BYE from VoIP gateway side when the remote caller hung up the phone...

This looks like a VoIP gateway side problem. We then made some internal testing to verify the expected behavior. Here are the results from the internal testing:

Expected behavior:

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

Note: The test response group has one member only so the response group application keeps ringing the same user

- The remote party calls the Response group number

- Response group answers the call and then it starts ringing the response group member (joe@contoso.com)

- Since the agent doesn’t pick up the phone for 15 seconds, it drops that session with a SIP CANCEL to the group member and it starts another session with the same agent (because there’s only one agent)

- The person calling from behind the VoIP gateway hangs up the phone after 23 seconds or so after the initial call

- So the second dialog with the agent is terminated

- The second call to the agent is made at 13:36:17

- The remote caller hangs up the phone at 13:36:22 (23 seconds after the response group answers the call)

- And the mediation server gets a SIP BYE from VoIP gateway since the remote caller hangs up the phone:

TL_INFO(TF_PROTOCOL) [0]0C4C.1410::11/23/2012-13:36:22.847.0002b91f (S4,SipMessage.DataLoggingHelper:sipmessage.cs(686))[3311788563]

<<<<<<<<<<<<Incoming SipMessage c=[<SipTlsConnection_386DD23>], 192.168.1.20:5071<-192.168.1.20:50807

BYE sip:napool.contoso.com:5071;grid;ms-fe=nafe02.contoso.com SIP/2.0

FROM: <sip:18006934501;phone-context=DefaultProfile@contoso.com;user=phone>;epid=8D443A6D50;tag=928547717d

TO: <sip:17042563016;phone-context=DefaultProfile@contoso.com;user=phone>;epid=14B9F3DDE9;tag=872d3a4ad0

CSEQ: 3828 BYE

CALL-ID: d9789202-c026-4661-88d8-adfc12c37995

MAX-FORWARDS: 69

VIA: SIP/2.0/TLS 192.168.1.20:50807;branch=z9hG4bK6FF51B0B.C998AF162BD50886;branched=FALSE

VIA: SIP/2.0/TLS 192.168.1.15:54616;branch=z9hG4bK97e1a6aa;ms-received-port=54616;ms-received-cid=726C00

CONTACT: <sip:nafe01.contoso.com@contoso.com;gruu;opaque=srvr:MediationServer:gJSXgywGXl2uoBnZnm4R7QAA;grid=1792a8d837324735acd180c81887b8b0>;isGateway

CONTENT-LENGTH: 0

SUPPORTED: ms-dialog-route-set-update

SUPPORTED: gruu-10

USER-AGENT: RTCC/4.0.0.0 MediationServer

P-ASSERTED-IDENTITY: "PBX 01"<sip:18006934501;phone-context=DefaultProfile@contoso.com;user=phone>

ms-diagnostics: 10027;source="nafe01.contoso.com";reason="Normal termination response from gateway after the call was established";component="MediationServer"

ms-diagnostics-public: 10027;reason="Normal termination response from gateway after the call was established";component="MediationServer"

ms-endpoint-location-data: NetworkScope;ms-media-location-type=intranet

------------EndOfIncoming SipMessage

Right after the SIP BYE is received from VoIP gateway, response group stops ringing the agent with a SIP CANCEL request:

We can see the same behavior in network trace as well:

=> The call starts and RTP traffic starts flowing:

=> At 15:36:23, VoIP gateway (Asteriks PBX) sends a SIP BYE to mediation server since the remote caller hangs up the phone, and the RTP traffic also stops at this point:

Summary:

========

We advised our customer to further check their VoIP gateway to better understand why it doesn’t send a SIP BYE to mediation server when the remote caller hangs up the phone (and because the SIP BYE is not received, response group member phones keep ringing)

Hope this helps

Thanks,

Murat

RDP connections might fail due to a problem with KB2621440 - MS12-020

2013-01-18T15:31:00Z

I was helping a colleague who was dealing with a Remote desktop connection problem where Windows 8 client was failing to access a certain Windows 2008 R2 SP1 Terminal server. We first collected some logs while reproducing the problem to better understand why the RDP connection was failing:

1) Please start TCPIP/Winsock ETL tracing on the client and on the Windows 2008 R2 TS from an elevated command prompt:

netsh trace start provider=Microsoft-Windows-TCPIP provider=Microsoft-Windows-Winsock-AFD tracefile=Terminalserver_tcpip_winsock.etl maxsize=500 capture=yes

Note: This command generates a lot of activity so we have to do the testing as fast as possible.

2) Please immediately reproduce the problem from the client by trying RDP connection. Right after the problem is reproduced please immediately stop netsh on the Windows 2008 R2 server first with the below command:

netsh trace stop

ANALYSIS:

========

After the logs were collected, I followed the below steps to further troubleshoot the issue:

=> The problem RDP session in the RDP server side ETL trace including network activity trace:

(ip.addr eq 10.0.107.58 and ip.addr eq 10.7.3.187) and (tcp.port eq 59193 and tcp.port eq 3389)

No. Time Delta Source Destination Protocol Length Info

5781 2013-01-06 09:52:15.407 0.000 10.0.107.58 10.7.3.187 TCP 66 59193 > 3389 [SYN] Seq=3976196062 Win=8192 Len=0 MSS=1380 WS=256

5782 2013-01-06 09:52:15.407 0.000 10.7.3.187 10.0.107.58 TCP 62 3389 > 59193 [SYN, ACK] Seq=3028123794 Ack=3976196063 Win=8192 Len=0 MSS=1460 WS=256

5783 2013-01-06 09:52:15.447 0.039 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976196063 Ack=3028123795 Win=66048 Len=0

5784 2013-01-06 09:52:15.448 0.000 10.0.107.58 10.7.3.187 TPKT 73 CR TPDU src-ref: 0x0000 dst-ref: 0x0000[Unreassembled Packet]

5785 2013-01-06 09:52:15.451 0.003 10.7.3.187 10.0.107.58 TCP 54 3389 > 59193 [ACK] Seq=3028123795 Ack=3976196082 Win=66048 Len=0

5786 2013-01-06 09:52:15.458 0.007 10.7.3.187 10.0.107.58 TPKT 73 CC TPDU src-ref: 0x1234 dst-ref: 0x0000[Unreassembled Packet]

5787 2013-01-06 09:52:15.520 0.062 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976196082 Ack=3028123814 Win=66048 Len=0

5958 2013-01-06 09:52:22.632 7.111 10.0.107.58 10.7.3.187 TPKT 218 Continuation

5959 2013-01-06 09:52:22.632 0.000 10.7.3.187 10.0.107.58 TPKT 912 Continuation

5971 2013-01-06 09:52:22.678 0.045 10.0.107.58 10.7.3.187 TPKT 380 Continuation

5972 2013-01-06 09:52:22.696 0.018 10.7.3.187 10.0.107.58 TPKT 113 Continuation

5975 2013-01-06 09:52:22.752 0.055 10.0.107.58 10.7.3.187 TPKT 235 Continuation

5976 2013-01-06 09:52:22.753 0.000 10.7.3.187 10.0.107.58 TPKT 1211 Continuation

5977 2013-01-06 09:52:22.809 0.055 10.0.107.58 10.7.3.187 TPKT 1434 Continuation

5978 2013-01-06 09:52:22.809 0.000 10.7.3.187 10.0.107.58 TCP 54 3389 > 59193 [ACK] Seq=3028125888 Ack=3976198133 Win=65792 Len=0

5979 2013-01-06 09:52:22.809 0.000 10.0.107.58 10.7.3.187 TPKT 263 Continuation

5980 2013-01-06 09:52:22.810 0.001 10.7.3.187 10.0.107.58 TPKT 315 Continuation

...

8129 2013-01-06 09:52:49.090 0.094 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976208206 Ack=3028242245 Win=64768 Len=0

8154 2013-01-06 09:52:49.526 0.436 10.7.3.187 10.0.107.58 TPKT 139 Continuation

8164 2013-01-06 09:52:49.620 0.093 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976208206 Ack=3028242330 Win=64768 Len=0

8170 2013-01-06 09:52:49.673 0.052 10.0.107.58 10.7.3.187 TPKT 123 Continuation

8180 2013-01-06 09:52:49.776 0.102 10.7.3.187 10.0.107.58 TPKT 683 Continuation

8186 2013-01-06 09:52:49.874 0.097 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976208275 Ack=3028242959 Win=66048 Len=0

8254 2013-01-06 09:52:52.475 2.600 10.7.3.187 10.0.107.58 TPKT 91 Continuation

8257 2013-01-06 09:52:52.567 0.092 10.0.107.58 10.7.3.187 TCP 60 59193 > 3389 [ACK] Seq=3976208275 Ack=3028242996 Win=66048 Len=0

10717 2013-01-06 09:53:40.765 48.198 10.7.3.187 10.0.107.58 TCP 54 3389 > 59193 [RST, ACK] Seq=3028242996 Ack=3976208275 Win=0 Len=0

The RDP server resets the existing RDP session. Interestingly all following RDP session attempts are immediately RESET:

I decided to check why TCPIP driver was reseting all incoming connection attempts from the ETL trace:

61714 8:53:53 AM 1/6/2013 111.1142353 Idle (0) 10.0.107.58 10.7.3.187 TCP TCP:Flags=......S., SrcPort=59210, DstPort=MS WBT Server(3389), PayloadLen=0, Seq=2885139468, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192

61715 8:53:53 AM 1/6/2013 111.1142441 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCPIP: NBL 0x0000000039EE1B40 fell off the receive fast path, Reason: Session state is not compatible. Protocol = TCP, Family = IPV4, Number of NBLs = 1 (0x1). SourceAddress = 10.0.107.58 Null. DestAddress = 10.7.3.187 Null.

61716 8:53:53 AM 1/6/2013 111.1142562 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCPIP: Transport (Protocol TCP, AddressFamily = IPV4) dropped 1 (0x1) packet(s) with Source = 10.7.3.187:3389, Destination = 10.0.107.58:59210. Reason = Transport endpoint was not found.

61717 8:53:53 AM 1/6/2013 111.1142853 Idle (0) 10.7.3.187 10.0.107.58 TCP TCP: [Bad CheckSum]Flags=...A.R.., SrcPort=MS WBT Server(3389), DstPort=59210, PayloadLen=0, Seq=0, Ack=2885139469, Win=0

that means there’s no process listening on TCP 3389. When we check the netstat output collected from RDP server, we really don’t see a process listening on that port:

TCP 0.0.0.0:80 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:135 0.0.0.0:0 LISTENING 920 InHost

TCP 0.0.0.0:443 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:445 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:4279 0.0.0.0:0 LISTENING 5796 InHost

TCP 0.0.0.0:5279 0.0.0.0:0 LISTENING 5796 InHost

TCP 0.0.0.0:8530 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:8531 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:47001 0.0.0.0:0 LISTENING 4 InHost

TCP 0.0.0.0:49152 0.0.0.0:0 LISTENING 636 InHost

TCP 0.0.0.0:49153 0.0.0.0:0 LISTENING 232 InHost

TCP 0.0.0.0:49154 0.0.0.0:0 LISTENING 240 InHost

TCP 0.0.0.0:49155 0.0.0.0:0 LISTENING 740 InHost

TCP 0.0.0.0:49156 0.0.0.0:0 LISTENING 724 InHost

TCP 0.0.0.0:49161 0.0.0.0:0 LISTENING 3048 InHost

TCP 10.7.3.187:80 10.193.10.7:49684 ESTABLISHED 4 InHost

=> Also at the exact time which matches the time of initial RDP connection being reset, we see the following event on RDP server which explains why the current connection is reset and the new ones are reset as well:

Error 1/6/2013 8:54:40 AM Service Control Manager 7034 None

The Remote Desktop Services service terminated unexpectedly. It has done this 3 time(s).

My colleague kept troubleshooting the problem from Terminal server perspective and they found out that http://support.microsoft.com/kb/2621440/en-us was re-published due to an initial problem with the security update. After reinstalling the security update, the issue was resolved.

Hope this helps you when dealing with similar problems.

Thanks,

Murat

Desktop sharing fails between federated contacts running Lync 2010 clients

2013-01-18T15:14:00Z

I would like to talk about another Lync 2010 problem where desktop sharing was failing between two federated contacts. Network traces and Lync ETL traces were collected while reproducing the problem. Here’s the troubleshooting steps that I followed:

ANALYSIS:

========

Note: Please note that usernames, IP addresses, server names etc are all replaced for privacy purposes.

Client IP: 10.98.2.1 (this is the client that initiates desktop sharing)

FE server IP: 10.10.10.1

Edge server internal IP: 10.3.0.34

Edge server external IP: 10.3.0.40

Edge server external IP (NATed): 2.2.2.2

Remote Edge server IP: 1.1.1.1

1) I started with Lync client side ETL trace. It negotiates the application sharing media port with the help of Edge server:

=> Application sharing request sent by the internal client:

12/10/2012|10:43:06.703 24F8:2648 INFO :: Sending Packet - 10.10.10.1:5061 (From Local Address: 10.98.2.1:51647) 2520 bytes:

12/10/2012|10:43:06.703 24F8:2648 INFO :: INVITE sip:user2@fabrikam.com SIP/2.0

Via: SIP/2.0/TLS 10.98.2.1:51647

Max-Forwards: 70

From: <sip:user1@contoso.com>;tag=2cd64ff7dc;epid=6750f01948

To: <sip:user2@fabrikam.com>

Call-ID: a622d7b9f6464be3a455e6d98ec700b3

CSeq: 1 INVITE

Contact: <sip:user1@contoso.com;opaque=user:epid:lxH-F4F2KFaOdejdehenrlAAA;gruu>

User-Agent: UCCAPI/4.0.7577.4356 OC/4.0.7577.4356 (Microsoft Lync 2010)

Supported: ms-dialog-route-set-update

Supported: timer

Supported: histinfo

Supported: ms-safe-transfer

Supported: ms-sender

Supported: ms-early-media

Supported: ms-conf-invite

Ms-Conversation-ID: Ac3Wuri73DV0XRhGRBSO/PHZU2QhhQ==

ms-keep-alive: UAC;hop-hop=yes

Allow: INVITE, BYE, ACK, CANCEL, INFO, UPDATE, REFER, NOTIFY, BENOTIFY, OPTIONS

ms-subnet: 10.98.22.0

ms-endpoint-location-data: NetworkScope;ms-media-location-type=Intranet

...

v=0

o=- 0 0 IN IP4 2.2.2.2

s=session

c=IN IP4 2.2.2.2

b=CT:99980

t=0 0

m=applicationsharing 58138 TCP/RTP/AVP 127

a=ice-ufrag:PFb1

a=candidate:1 1 TCP-PASS 2120613887 10.98.2.1 21916 typ host

a=candidate:1 2 TCP-PASS 2120613374 10.98.2.1 21916 typ host

a=candidate:2 1 TCP-ACT 2121006591 10.98.2.1 18574 typ host

a=candidate:2 2 TCP-ACT 2121006078 10.98.2.1 18574 typ host

a=candidate:3 1 TCP-PASS 6556159 2.2.2.2 58138 typ relay raddr 10.98.2.1 rport 13211

a=candidate:3 2 TCP-PASS 6556158 2.2.2.2 58138 typ relay raddr 10.98.2.1 rport 13211

...

=> Final response:

12/10/2012|10:43:10.418 24F8:2648 INFO :: Data Received - 10.10.10.1:5061 (To Local Address: 10.98.2.1:51647) 4311 bytes:

12/10/2012|10:43:10.418 24F8:2648 INFO :: SIP/2.0 200 OK

Authentication-Info: TLS-DSK qop="auth", opaque="2957C393", srand="ACCCF975", snum="68", rspauth="8dad7b71a068c9ec073868375fcd97955d8dd4bf", targetname="fepool01.contoso.com", realm="SIP Communications Service", version=4

Via: SIP/2.0/TLS 10.98.2.1:51647;ms-received-port=51647;ms-received-cid=657300

From: "user1 @ contoso.com"<sip:user1@contoso.com>;tag=2cd64ff7dc;epid=6750f01948

To: <sip:user2@fabrikam.com>;epid=c23c88d032;tag=fef0c3e438

Call-ID: a622d7b9f6464be3a455e6d98ec700b3

CSeq: 1 INVITE

...

Contact: <sip:user2@fabrikam.com;opaque=user:epid:wyPrDAU4lVq4GhmnrWqEFgAA;gruu>

User-Agent: UCCAPI/4.0.7577.4356 OC/4.0.7577.4356 (Microsoft Lync 2010)

Supported: histinfo

Supported: ms-safe-transfer

Supported: ms-dialog-route-set-update

Supported: ms-conf-invite

Allow: INVITE, BYE, ACK, CANCEL, INFO, UPDATE, REFER, NOTIFY, BENOTIFY, OPTIONS

Session-Expires: 720;refresher=uac

ms-client-diagnostics: 51007;reason="Callee media connectivity diagnosis info";CalleeMediaDebug="application-sharing:ICEWarn=0x0,LocalSite=10.166.24.59:8541,LocalMR=1.1.1.1:50704,RemoteSite=10.98.2.1:21916,RemoteMR=2.2.2.2:58138,PortRange=50040:50059,LocalMRTCPPort=50704,RemoteMRTCPPort=58138,LocalLocation=1,RemoteLocation=2,FederationType=1"

ms-endpoint-location-data: NetworkScope;ms-media-location-type=Internet

...

v=0

o=- 0 0 IN IP4 1.1.1.1

s=session

c=IN IP4 1.1.1.1

b=CT:99980

t=0 0

m=applicationsharing 50704 TCP/RTP/SAVP 127

a=ice-ufrag:G/Yw

a=ice-pwd:EwhnzgwKgaoRuI2T2gKRRqYz

a=candidate:1 1 TCP-PASS 2120613887 10.26.10.50 50058 typ host

a=candidate:1 2 TCP-PASS 2120613374 10.26.10.50 50058 typ host

...

So we expect the media session to flow between 1.1.1.1:50704 <---> 2.2.2.2:58138 (between the two Edge servers: Edge server @ contoso.com and Edge server @ fabrikam.com)

On the other hand, the internal client from where the user (user1@contoso.com) signed in will be accessing the Edge server @ contoso.com at TCP 443 (Mediarelay service listens on internal interface of the Edge server as well)

In summary, the communication should be as follows:

Flow1:

Internal client <--- > Edge server @ consoto.com internal interface:443

Flow2:

Edge server external interface (contoso.com) <---> Edge server external interface (fabrikam.com) (1.1.1.1:50704 <---> 2.2.2.2:58138)

a) When I check the trace collected on Edge server, I see that the client has a successful session with the internal interface of the Edge server @ TCP 443:

No. Time Delta Source Destination Protocol Length Info

344 2012-12-10 10:43:49.130 0.000 10.98.2.1 10.3.0.34 TCP 66 13211 > 443 [SYN] Seq=2226089608 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

345 2012-12-10 10:43:49.130 0.000 10.3.0.34 10.98.2.1 TCP 66 443 > 13211 [SYN, ACK] Seq=3794450141 Ack=2226089609 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

346 2012-12-10 10:43:49.131 0.000 10.98.2.1 10.3.0.34 TCP 60 13211 > 443 [ACK] Seq=2226089609 Ack=3794450142 Win=65536 Len=0

347 2012-12-10 10:43:49.181 0.049 10.98.2.1 10.3.0.34 TLSv1 104 Client Hello

348 2012-12-10 10:43:49.181 0.000 10.3.0.34 10.98.2.1 TLSv1 137 Server Hello, Server Hello Done

349 2012-12-10 10:43:49.234 0.053 10.98.2.1 10.3.0.34 TLSv1 178 Ignored Unknown Record

350 2012-12-10 10:43:49.234 0.000 10.3.0.34 10.98.2.1 TLSv1 189 Ignored Unknown Record

354 2012-12-10 10:43:49.286 0.051 10.98.2.1 10.3.0.34 TLSv1 240 Ignored Unknown Record

355 2012-12-10 10:43:49.286 0.000 10.3.0.34 10.98.2.1 TLSv1 178 Ignored Unknown Record

358 2012-12-10 10:43:49.480 0.194 10.98.2.1 10.3.0.34 TCP 60 13211 > 443 [ACK] Seq=2226089969 Ack=3794450484 Win=65280 Len=0

420 2012-12-10 10:43:53.067 3.586 10.98.2.1 10.3.0.34 TLSv1 328 Ignored Unknown Record

...

b) But the Edge server @ contoso.com fails to connect to Edge server @ fabrikam.com at the negotiated port:

Note: Since this trace is collected on Edge server, we see the private IP address (10.3.0.40) assigned to external interface of the AV Edge service on Edge server.

No. Time Delta Source Destination Protocol Length Info

1299 2012-12-10 10:43:59.456 0.000 10.3.0.40 1.1.1.1 TCP 66 58138 > 50704 [SYN] Seq=3074395695 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

1300 2012-12-10 10:43:59.499 0.042 1.1.1.1 10.3.0.40 TCP 60 50704 > 58138 [RST, ACK] Seq=0 Ack=3074395696 Win=0 Len=0

1353 2012-12-10 10:44:00.002 0.503 10.3.0.40 1.1.1.1 TCP 66 58138 > 50704 [SYN] Seq=3074395695 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

1356 2012-12-10 10:44:00.044 0.042 1.1.1.1 10.3.0.40 TCP 60 50704 > 58138 [RST, ACK] Seq=0 Ack=3074395696 Win=0 Len=0

1360 2012-12-10 10:44:00.548 0.503 10.3.0.40 1.1.1.1 TCP 62 58138 > 50704 [SYN] Seq=3074395695 Win=8192 Len=0 MSS=1460 SACK_PERM=1

1361 2012-12-10 10:44:00.590 0.042 1.1.1.1 10.3.0.40 TCP 60 50704 > 58138 [RST, ACK] Seq=0 Ack=3074395696 Win=0 Len=0

it gets a TCP RST to its connection attempts (like frame #1300, frame #1356, frame #1361). So the media session (application sharing) couldn’t be established.

We have to allow Edge server so that it could establish outbound TCP connections within this range for media communications:

http://technet.microsoft.com/en-us/library/gg425891(v=ocs.14).aspx Reference Architecture 1: Port Summary for Single Consolidated Edge

Summary:

========

After further investigation by our customer’s networking team, it was found out that the checkpoint firewall was not allowing outbound TCP connections in 50000-59999 port range and hence application sharing was failing.

Hope this helps you in resolving similar problems...

Thanks,

Murat

External users cannot sign in to Lync 2010

2013-01-18T15:03:00Z

Today I’ll be talking about a problem where the external Lync 2010 clients fail to sign in through Lync 2010 Edge server intermittently and rebooting the Edge server helps resolve the issue for sometime until the problem reappears. There could be multiple problems that might prevent an external user from signing in successfully like authentication issues, service problems, communication problems so on and so forth. In this instance it was a pure communications problem. Let me explain how I troubleshooted this issue now...

First of all we collected a number of logs from relevant systems to better understand at which point the sign-in process was failing. Taking corrective actions without logs is generally shooting in the dark so the best way to deal with a problem is to cover the problem with appropriate logs. Here is the action plan that was used to collect the logs when the problem occurred:

Action plan:

=========

1) Please wait until the issue occurs and then run the following commands on respective systems once the issue occurs:

=> On Edge server:

- Please start a new network trace

- Please start SIPStack & S4 logging

- Please run the following command from an elevated command prompt:

netsh trace start provider=Microsoft-Windows-TCPIP provider=Microsoft-Windows-Winsock-AFD tracefile=Edge_tcpip_winsock.etl maxsize=500 capture=yes

=> On Frontend server:

- Please start a new network trace

- Please start SIPStack & S4 logging

- Please run the following command from an elevated command prompt:

netsh trace start provider=Microsoft-Windows-TCPIP provider=Microsoft-Windows-Winsock-AFD tracefile=FE_tcpip_winsock.etl maxsize=500 capture=yes

=> On the internal client:

- Please enable Lync tracing from Lync client

=> On the external client:

- Please enable Lync tracing from Lync client

3) Now please reproduce the problem with signing in with a user from the external client

4) Now please stop logging on all endpoints. (network traces, Lync client side logging, Lync server side logging). You can also run the following command to stop netsh tracing on Edge and Frontend servers:

netsh trace stop

Troubleshooting:

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

After the logs were collected as per the action plan, I analyzed them starting from external client side:

Note: Please note that all IP addresses, server names, user names etc are replaced for privacy purposes.

External client IP: 10.1.1.1

Access Edge IP: 172.16.1.1

Edge internal IP: 192.168.1.1

FE server IP: 192.168.3.10

1) Remote client to Edge server activity

- Remote client has SIP connectivity to Edge server but those sessions are closed shortly after the session is established

Example:

ip.addr==10.1.1.1 and tcp.port==62973

No. Time Delta Source Destination Protocol Length Info

4298 2013-01-08 09:18:53.832 0.000 10.1.1.1 172.16.1.1 TCP 66 62973 > 443 [SYN] Seq=2046472569 Win=8192 Len=0 MSS=1380 WS=4 SACK_PERM=1

4299 2013-01-08 09:18:53.832 0.000 172.16.1.1 10.1.1.1 TCP 62 443 > 62973 [SYN, ACK] Seq=4248548130 Ack=2046472570 Win=8192 Len=0 MSS=1460 SACK_PERM=1

4313 2013-01-08 09:18:54.441 0.609 10.1.1.1 172.16.1.1 TCP 60 62973 > 443 [ACK] Seq=2046472570 Ack=4248548131 Win=16560 Len=0

4316 2013-01-08 09:18:56.020 1.578 10.1.1.1 172.16.1.1 TLSv1 181 Client Hello

4317 2013-01-08 09:18:56.037 0.016 172.16.1.1 10.1.1.1 TLSv1 1434 Server Hello, Certificate[Unreassembled Packet]

4318 2013-01-08 09:18:56.037 0.000 172.16.1.1 10.1.1.1 TLSv1 1434 Ignored Unknown Record

4319 2013-01-08 09:18:56.417 0.380 10.1.1.1 172.16.1.1 TCP 60 62973 > 443 [ACK] Seq=2046472697 Ack=4248550891 Win=16560 Len=0

4320 2013-01-08 09:18:56.417 0.000 172.16.1.1 10.1.1.1 TLSv1 1434 Ignored Unknown Record

4321 2013-01-08 09:18:56.417 0.000 172.16.1.1 10.1.1.1 TLSv1 560 Ignored Unknown Record

4322 2013-01-08 09:18:56.787 0.370 10.1.1.1 172.16.1.1 TCP 60 62973 > 443 [ACK] Seq=2046472697 Ack=4248552777 Win=16560 Len=0

4323 2013-01-08 09:18:56.791 0.004 10.1.1.1 172.16.1.1 TLSv1 380 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message

4324 2013-01-08 09:18:56.796 0.004 172.16.1.1 10.1.1.1 TLSv1 113 Change Cipher Spec, Encrypted Handshake Message

4327 2013-01-08 09:18:57.193 0.397 10.1.1.1 172.16.1.1 TLSv1 379 Application Data

4328 2013-01-08 09:18:57.196 0.003 172.16.1.1 10.1.1.1 TLSv1 475 Application Data

4333 2013-01-08 09:18:57.599 0.402 10.1.1.1 172.16.1.1 TLSv1 891 Application Data

4337 2013-01-08 09:18:57.802 0.203 172.16.1.1 10.1.1.1 TCP 54 443 > 62973 [ACK] Seq=4248553257 Ack=2046474185 Win=64860 Len=0

4506 2013-01-08 09:19:18.612 20.809 172.16.1.1 10.1.1.1 TLSv1 507 Application Data

4509 2013-01-08 09:19:19.094 0.482 10.1.1.1 172.16.1.1 TCP 60 62973 > 443 [FIN, ACK] Seq=2046474185 Ack=4248553710 Win=15627 Len=0

4510 2013-01-08 09:19:19.094 0.000 172.16.1.1 10.1.1.1 TCP 54 443 > 62973 [ACK] Seq=4248553710 Ack=2046474186 Win=64860 Len=0

4511 2013-01-08 09:19:19.094 0.000 172.16.1.1 10.1.1.1 TCP 54 443 > 62973 [RST, ACK] Seq=4248553710 Ack=2046474186 Win=0 Len=0

Approximately 21 seconds later Edge server returns the response to Client (SIP server timeout) and that the connection is closed. I’ll explain from where that 21 seconds come from later.

=> Looking at the same activity from Edge server SIPStack log:

TL_INFO(TF_PROTOCOL) [0]05E0.0AAC::01/08/2013-09:18:57.600.02e733e9 (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record

Trace-Correlation-Id: 3490147474

Instance-Id: 000AE0DB

Direction: incoming;source="external edge";destination="internal edge"

Peer: 10.1.1.1:62973

Message-Type: request

Start-Line: REGISTER sip:contoso.com SIP/2.0

From: <sip:username@contoso.com>;tag=eee093290f;epid=927c603558

To: <sip:username@contoso.com>

CSeq: 1 REGISTER

Call-ID: 20d82282a7d94f4fb66a0a6df0c0377f

Via: SIP/2.0/TLS 192.168.2.98:62973

Max-Forwards: 70

Contact: <sip:192.168.2.98:62973;transport=tls;ms-opaque=6b23bb065a>;methods="INVITE, MESSAGE, INFO, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace;+sip.instance="<urn:uuid:7C426EA7-E80D-53A0-95E6-ED07D8D0CD1E>"

User-Agent: UCCAPI/4.0.7577.4356 OC/4.0.7577.4356 (Microsoft Lync 2010)

Supported: gruu-10, adhoclist, msrtc-event-categories

Supported: ms-forking

Supported: ms-cluster-failover

Supported: ms-userservices-state-notification

ms-keep-alive: UAC;hop-hop=yes

Event: registration

Content-Length: 0

Message-Body:

TL_ERROR(TF_DIAG) [0]05E0.0AAC::01/08/2013-09:19:18.612.02e7707a (SIPStack,SIPAdminLog::TraceDiagRecord:SIPAdminLog.cpp(143))$$begin_record

LogType: diagnostic

Severity: error

Text: Message was not sent because the connection was closed

SIP-Start-Line: REGISTER sip:contoso.com SIP/2.0

SIP-Call-ID: 20d82282a7d94f4fb66a0a6df0c0377f

SIP-CSeq: 1 REGISTER

Peer: fepool1.contoso.com:5061

and the response back to client:

TL_INFO(TF_PROTOCOL) [0]05E0.0AAC::01/08/2013-09:19:18.613.02e7734c (SIPStack,SIPAdminLog::TraceProtocolRecord:SIPAdminLog.cpp(125))$$begin_record

Trace-Correlation-Id: 3490147474

Instance-Id: 000AE0E9

Direction: outgoing;source="local";destination="external edge"

Peer: 10.1.1.1:62973

Message-Type: response

Start-Line: SIP/2.0 504 Server time-out

From: <sip:username@contoso.com>;tag=eee093290f;epid=927c603558

To: <sip:username@contoso.com>;tag=586991893A5520DA53F83BE6C4EBF4F9

CSeq: 1 REGISTER

Call-ID: 20d82282a7d94f4fb66a0a6df0c0377f

ms-user-logon-data: RemoteUser

Via: SIP/2.0/TLS 192.168.2.98:62973;received=10.1.1.1;ms-received-port=62973;ms-received-cid=2E6400

Server: RTC/4.0

Content-Length: 0

Message-Body:

2) Communication between the Edge and Frontend servers:

=> Edge server side trace:

- Edge server try to connect to Frontend server at TCP port 5061 but it fails to do so after three attempts:

106631 11:18:57 AM 1/8/2013 713.5078058 RTCSrv.exe (1504) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=0, Win=8192 ( ) = 8192

106984 11:19:00 AM 1/8/2013 716.5111523 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:[SynReTransmit #106631]Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=0, Win=8192 ( ) = 8192

107347 11:19:06 AM 1/8/2013 722.5093069 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:[SynReTransmit #106631]Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=0, Win=8192 ( ) = 8192

=> Now let’s see the same activity from TCPIP/AFD drivers perspective:

- RTCSrv process on Edge server creates a stream type socket and binds to it (TCPIP driver assigns a local port 50375) and then requests for a connect to 192.168.3.10:5061

106612 11:18:57 AM 1/8/2013 713.4871675 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:socket: 0 (0x0): Process 0x0000000007AE3060 (0x00000000000005E0), Endpoint 0x0000000007A05010, Family 2 (0x2), Type SOCK_STREAM, Protocol 6 (0x6), Seq 1006 (0x3EE), Status Success

106613 11:18:57 AM 1/8/2013 713.4872298 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV4 PID=1504 (0x5E0)) created.

106614 11:18:57 AM 1/8/2013 713.4872311 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x00000000082D19B0 (Family=IPV4, PID=1504 (0x5E0)) created with status = Success.

106615 11:18:57 AM 1/8/2013 713.4872401 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:socket: 1 (0x1): Process 0x0000000007AE3060 (0x00000000000005E0), Endpoint 0x0000000007A05010, Family 0 (0x0), Type Unknown value: 0, Protocol 0 (0x0), Seq 1013 (0x3F5), Status Success

106617 11:18:57 AM 1/8/2013 713.5075474 RTCSrv.exe (1504) 192.168.1.1 Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:bind: 0 (0x0): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Address 192.168.1.1:0, Seq 7010 (0x1B62), Status Success

106618 11:18:57 AM 1/8/2013 713.5075751 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000082D19B0 acquired port number 50357 (0xC4B5).

106619 11:18:57 AM 1/8/2013 713.5075798 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.1:50357) bound.

106620 11:18:57 AM 1/8/2013 713.5075837 RTCSrv.exe (1504) 192.168.1.1 Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:bind: 1 (0x1): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Address 192.168.1.1:50357, Seq 7022 (0x1B6E), Status Success

106621 11:18:57 AM 1/8/2013 713.5076201 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:Socket option: 4 (0x4): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Option FIONBIO, Value 1 (0x1), Seq 11002 (0x2AFA), Status Success

106622 11:18:57 AM 1/8/2013 713.5076435 RTCSrv.exe (1504) 192.168.3.10 Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:connect: 0 (0x0): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Address 192.168.3.10:5061, Seq 5023 (0x139F), Status Success

106623 11:18:57 AM 1/8/2013 713.5076564 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 transition from ClosedState to SynSentState, SndNxt = 0 (0x0).

106624 11:18:57 AM 1/8/2013 713.5076832 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 attempted to acquire weak reference on port number 50357 (0xC4B5) inherited from endpoint 0x00000000082D19B0. Successful = TRUE.

106625 11:18:57 AM 1/8/2013 713.5076863 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) requested to connect.

106626 11:18:57 AM 1/8/2013 713.5077111 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Inspect Connect has been completed on Tcb 0x000000000829C860 with status = Success.

106627 11:18:57 AM 1/8/2013 713.5077296 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x000000000829C860 is going to output SYN with ISN = 2232090326 (0x850AFED6), RcvWnd = 8192 (0x2000), RcvWndScale = 0 (0x0).

106628 11:18:57 AM 1/8/2013 713.5077335 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) connect proceeding.

106629 11:18:57 AM 1/8/2013 713.5077421 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 SRTT measurement started (seq = 2232090326 (0x850AFED6), tick = 233642658 (0xDED1AA2)).

106630 11:18:57 AM 1/8/2013 713.5077433 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer started. Scheduled to expire in 3000 (0xBB8) ms.

=> As a result of the upper layer activity, the first SYN sent to the wire:

106631 11:18:57 AM 1/8/2013 713.5078058 RTCSrv.exe (1504) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=0, Win=8192 ( ) = 8192

- After 3 seconds, the second SYN is sent because the retransmit timer has expired:

106979 11:19:00 AM 1/8/2013 716.5110434 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer has expired.

106980 11:19:00 AM 1/8/2013 716.5110467 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860: Send Retransmit round with SndUna = 2232090326 (0x850AFED6), Round = 1 (0x1), SRTT = 0 (0x0), RTO = 300 (0x12C).

106981 11:19:00 AM 1/8/2013 716.5110498 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) retransmitting connect attempt, RexmitCount = 1 (0x1).

106982 11:19:00 AM 1/8/2013 716.5110733 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860: SRTT measurement cancelled.

106983 11:19:00 AM 1/8/2013 716.5110861 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer started. Scheduled to expire in 6000 (0x1770) ms.

=> The second SYN sent to the wire:

- After 6 seconds, the third SYN is sent because the retransmit timer has expired:

107342 11:19:06 AM 1/8/2013 722.5091976 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer has expired.

107343 11:19:06 AM 1/8/2013 722.5092010 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860: Send Retransmit round with SndUna = 2232090326 (0x850AFED6), Round = 2 (0x2), SRTT = 0 (0x0), RTO = 300 (0x12C).

107344 11:19:06 AM 1/8/2013 722.5092043 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) retransmitting connect attempt, RexmitCount = 2 (0x2).

107345 11:19:06 AM 1/8/2013 722.5092289 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860: SRTT measurement cancelled.

107346 11:19:06 AM 1/8/2013 722.5092418 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer started. Scheduled to expire in 12000 (0x2EE0) ms.

=> The third SYN sent to the wire:

- After 12 seconds, TCPIP driver doesn’t send anymore TCP SYNs and terminates the connection attempt and the socket is closed.

107780 11:19:18 AM 1/8/2013 734.5061235 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000829C860 RetransmitTimer timer has expired.

107781 11:19:18 AM 1/8/2013 734.5061285 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) terminating: retransmission timeout expired.

107782 11:19:18 AM 1/8/2013 734.5061305 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) shutdown initiated (0xC00000B5 - STATUS_IO_TIMEOUT). PID = 1504 (0x5E0).

107783 11:19:18 AM 1/8/2013 734.5061347 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 transition from SynSentState to ClosedState, SndNxt = 2232090327 (0x850AFED7).

107784 11:19:18 AM 1/8/2013 734.5061433 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000829C860 (local=192.168.1.1:50357 remote=192.168.3.10:5061) connect attempt failed with status = 0xC00000B5 - STATUS_IO_TIMEOUT.

107785 11:19:18 AM 1/8/2013 734.5062093 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x000000000829C860 released port number 50357 (0xC4B5). WeakReference = TRUE.

107786 11:19:18 AM 1/8/2013 734.5062386 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:connect: 1 (0x1): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Seq 5024 (0x13A0), Status 0xC00000B5 - STATUS_IO_TIMEOUT

107787 11:19:18 AM 1/8/2013 734.5065252 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 0 (0x0): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Seq 2002 (0x7D2), Status Success

107788 11:19:18 AM 1/8/2013 734.5065297 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.1:50357) closed.

107789 11:19:18 AM 1/8/2013 734.5065339 RTCSrv.exe (1504) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000082D19B0 released port number 50357 (0xC4B5). WeakReference = FALSE.

107790 11:19:18 AM 1/8/2013 734.5065425 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 1 (0x1): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Seq 2003 (0x7D3), Status Success

107791 11:19:18 AM 1/8/2013 734.5065490 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:closesocket: 0 (0x0): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Seq 2000 (0x7D0), Status Success

107792 11:19:18 AM 1/8/2013 734.5065498 RTCSrv.exe (1504) Wscore_MicrosoftWindowsWinsockAFD Wscore_MicrosoftWindowsWinsockAFD:closesocket: 1 (0x1): Process 0x0000000007AE3060, Endpoint 0x0000000007A05010, Seq 2001 (0x7D1), Status Success

- So the connection times out after 21 seconds. This also explains why the external client to Edge server connection is terminated after 21 seconds. Since Edge server cannot access Frontend server, it returns a SIP 504 and then the client closes the session.

- Also the Edge server SIPSTack ETL trace confirms that behavior:

TL_ERROR(TF_CONNECTION) [0]05E0.0AAC::01/08/2013-09:19:18.611.02e77050 (SIPStack,SIPAdminLog::TraceConnectionRecord:SIPAdminLog.cpp(160))

$$begin_record

LogType: connection

Severity: error

Text: Failed to complete outbound connection

Peer-IP: 192.168.3.10:5061

Peer-FQDN: fepool01.contoso.com

Connection-ID: 0x2E6603

Transport: TLS

Result-Code: 0x8007274c WSAETIMEDOUT

Data: fqdn=" fepool01.contoso.com ";peer-type="InternalServer";winsock-code="10060"

$$end_record

- Also a telnet test confirms the same behavior:

Edge:

C:\Users\Administrator>telnet 192.168.3.10 5061

Connecting To 192.168.3.10...Could not open connection to the host, on port 5061: Connect failed

///////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

=> Frontend server side trace:

- Frontend server see the incoming connection requests like below:

606227 11:19:07 AM 1/8/2013 727.4974204 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=2948578651, Win=8192 ( ) = 8192

606232 11:19:07 AM 1/8/2013 727.4975478 Idle (0) 192.168.3.10 192.168.1.1 TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=5061, DstPort=50357, PayloadLen=0, Seq=154470907, Ack=2232090327, Win=8192 ( Scale factor not supported ) = 8192

606233 11:19:07 AM 1/8/2013 727.4980222 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=154470908, Win=8192

612948 11:19:10 AM 1/8/2013 730.5001959 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=2948578651, Win=8192 ( ) = 8192

612953 11:19:10 AM 1/8/2013 730.5003515 Idle (0) 192.168.3.10 192.168.1.1 TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=5061, DstPort=50357, PayloadLen=0, Seq=155953667, Ack=2232090327, Win=8192 ( Scale factor not supported ) = 8192

612967 11:19:10 AM 1/8/2013 730.5007007 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=155953668, Win=8192

623999 11:19:16 AM 1/8/2013 736.4983502 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=2948578651, Win=8192 ( ) = 8192

624004 11:19:16 AM 1/8/2013 736.4985345 Idle (0) 192.168.3.10 192.168.1.1 TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=5061, DstPort=50357, PayloadLen=0, Seq=157301184, Ack=2232090327, Win=8192 ( Scale factor not supported ) = 8192

624005 11:19:16 AM 1/8/2013 736.4987452 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=157301185, Win=8192

- It gets the TCP SYN from Edge, sends a TCP SYN ACK back to it but very shortly afterwards it gets a TCP RST from Frontend. In reality that TCP RST is not sent by the Edge server as we have seen above. Most likely that TCP RST comes from a network device running in between. The sender MAC address for that TCP RST is the following (but it doesn’t necessarily mean it’s that device sending the RST:)

Frame: Number = 606233, Captured Frame Length = 161, MediaType = NetEvent

+ NetEvent:

+ MicrosoftWindowsNDISPacketCapture: Packet Fragment (60 (0x3C) bytes)

- Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[ 00-50-56-33-22-11],SourceAddress:[ 00-0F-8F-11-22-33]

+ DestinationAddress: VMWare, Inc. 8C7B52 [00-50-56-33-22-11]

+ SourceAddress: Cisco Systems 112233 [00-0F-8F-11-22-33]

EthernetType: Internet IP (IPv4), 2048(0x800)

UnknownData: Binary Large Object (6 Bytes)

+ Ipv4: Src = 192.168.1.1, Dest = 192.168.3.10, Next Protocol = TCP, Packet ID = 50541, Total IP Length = 40

+ Tcp: Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=154470908, Win=8192

- Now let’s check the above activity at TCPIP/AFD driver level:

=> The first TCP SYN received from the network:

612948 11:19:10 AM 1/8/2013 730.5001959 Idle (0) 192.168.1.1 192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=2948578651, Win=8192 ( ) = 8192

=> TCPIP driver sends a TCP SYN ACK:

612949 11:19:10 AM 1/8/2013 730.5002398 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCPIP: NBL 0x000000000CCBE7F0 fell off the receive fast path, Reason: Session state is not compatible. Protocol = TCP, Family = IPV4, Number of NBLs = 1 (0x1). SourceAddress = 192.168.1.1 Null. DestAddress = 192.168.3.10 Null.

612950 11:19:10 AM 1/8/2013 730.5002968 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x0000000011D4DCF0 transition from ListenState to SynRcvdState, SndNxt = 0 (0x0).

612951 11:19:10 AM 1/8/2013 730.5003286 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x0000000011D4DCF0 SRTT measurement started (seq = 155953667 (0x94BAA03), tick = 1684327497 (0x6464CC49)).

612952 11:19:10 AM 1/8/2013 730.5003309 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x0000000011D4DCF0 RetransmitTimer timer started. Scheduled to expire in 3000 (0xBB8) ms.

612953 11:19:10 AM 1/8/2013 730.5003515 Idle (0) 192.168.3.10 192.168.1.1TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=5061, DstPort=50357, PayloadLen=0, Seq=155953667, Ack=2232090327, Win=8192 ( Scale factor not supported ) = 8192

- It gets a TCP RST from Edge server side right after this: (this wasn’t sent by the Edge server by the way)

612967 11:19:10 AM 1/8/2013 730.5007007 Idle (0) 192.168.1.1192.168.3.10 TCP TCP:Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=155953668, Win=8192

612968 11:19:10 AM 1/8/2013 730.5007382 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x0000000011D4DCF0 (local=192.168.3.10:5061 remote=192.168.1.1:50357) connection terminated: received RST.

612969 11:19:10 AM 1/8/2013 730.5007404 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x0000000011D4DCF0 (local=192.168.3.10:5061 remote=192.168.1.1:50357) shutdown initiated (0xC000020D - STATUS_CONNECTION_RESET). PID = 2640 (0xA50).

612970 11:19:10 AM 1/8/2013 730.5007432 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x0000000011D4DCF0 transition from SynRcvdState to ClosedState, SndNxt = 155953668 (0x94BAA04).

- The same action is repeated two more times:

623999 11:19:16 AM 1/8/2013 736.4983502 Idle (0) 192.168.1.1192.168.3.10 TCP TCP:Flags=......S., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090326, Ack=2948578651, Win=8192 ( ) = 8192

624000 11:19:16 AM 1/8/2013 736.4983890 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCPIP: NBL 0x000000000CCE1E20 fell off the receive fast path, Reason: Session state is not compatible. Protocol = TCP, Family = IPV4, Number of NBLs = 1 (0x1). SourceAddress = 192.168.1.1 Null. DestAddress = 192.168.3.10 Null.

624001 11:19:16 AM 1/8/2013 736.4984630 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000EDC7960 transition from ListenState to SynRcvdState, SndNxt = 0 (0x0).

624002 11:19:16 AM 1/8/2013 736.4985060 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000EDC7960 SRTT measurement started (seq = 157301184 (0x96039C0), tick = 1684328097 (0x6464CEA1)).

624003 11:19:16 AM 1/8/2013 736.4985125 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Connection 0x000000000EDC7960 RetransmitTimer timer started. Scheduled to expire in 3000 (0xBB8) ms.

624004 11:19:16 AM 1/8/2013 736.4985345 Idle (0) 192.168.3.10 192.168.1.1TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=5061, DstPort=50357, PayloadLen=0, Seq=157301184, Ack=2232090327, Win=8192 ( Scale factor not supported ) = 8192

624005 11:19:16 AM 1/8/2013 736.4987452 Idle (0) 192.168.1.1192.168.3.10 TCP TCP:Flags=...A.R.., SrcPort=50357, DstPort=5061, PayloadLen=0, Seq=2232090327, Ack=157301185, Win=8192

624006 11:19:16 AM 1/8/2013 736.4987656 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000EDC7960 (local=192.168.3.10:5061 remote=192.168.1.1:50357) connection terminated: received RST.

624007 11:19:16 AM 1/8/2013 736.4987684 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000EDC7960 (local=192.168.3.10:5061 remote=192.168.1.1:50357) shutdown initiated (0xC000020D - STATUS_CONNECTION_RESET). PID = 2640 (0xA50).

624008 11:19:16 AM 1/8/2013 736.4987706 Idle (0) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x000000000EDC7960 transition from SynRcvdState to ClosedState, SndNxt = 157301185 (0x96039C1).

...

SUMMARY:

=========

The behavior we see above points to a problem somewhere between at or below the NIC layer on Frontend server and at or below the NIC layer on Edge server including any network devices sitting in the path in between the two servers like LAN switches, firewalls etc.

As such, I have made the following recommendations to our customer

a) Involving their networking team for further investigations on the network devices running in between the Edge and frontend servers

b) Making some improvements on the endpoints (edge/frontend servers) from vmware perspective since both servers are virtualized on vmware ESX server(s)

=> The NIC could be configured as a VMXNET3 driver in the vmware config:

http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1001805

Choosing a network adapter for your virtual machine

=> Vmware recommends turning STP protocol off on the switchport to which VMware ESX server is connected:

http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1003804

STP may cause temporary loss of network connectivity when a failover or failback event occurs

=> We can check if the current physical NIC is on the compatibility list of Vmware:

http://partnerweb.vmware.com/comp_guide2/search.php?

(Please choose your vmware server version and network adapter brand/model from the above link)

=> Vmware releases patches on releated components. For example the following is one of the latest releases for ESXi 4.0. It is best to check if your Vmware server binaries are recent.

http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=2011768

=> Also it’s suggested to run virtual machine version 7 for the guest:

http://www.vm-help.com/esx40i/upgrade_virtual_hardware/virtual_hardware_upgrade.php

Hope this helps you in troubleshooting similar problems...

Thanks,

Murat

SCCM client push installation may fail due to firewall problems

2013-01-06T16:15:00Z

I was collaborating with a colleague of mine on a problem where SCCM client push installation was failing. They suspected network connectivity problems and collected simultaneous network traces from SCCM server and from a problem client machine and involved me in for further analysis.

When I check the SCCM server and client side traces, I saw that SCCM server was successfully accessing the client through TCP port 135

=> SCCM server side trace:

- TCP three way handshake between SCCM server and client:

5851 14:42:47 05.09.2012 34.0337296 10.0.9.149 CLIENTNAME.company.com TCP TCP: [Bad CheckSum]Flags=......S., SrcPort=51763, DstPort=DCE endpoint resolution(135), PayloadLen=0, Seq=2250995253, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:861, IPv4:843}

5852 14:42:47 05.09.2012 34.0364843 CLIENTNAME.company.com 10.0.9.149 TCP TCP:Flags=...A..S., SrcPort=DCE endpoint resolution(135), DstPort=51763, PayloadLen=0, Seq=1315818582, Ack=2250995254, Win=65535 ( Negotiated scale factor 0x0 ) = 65535 {TCP:861, IPv4:843}

5853 14:42:47 05.09.2012 34.0365076 10.0.9.149 CLIENTNAME.company.com TCP TCP: [Bad CheckSum]Flags=...A...., SrcPort=51763, DstPort=DCE endpoint resolution(135), PayloadLen=0, Seq=2250995254, Ack=1315818583, Win=258 (scale factor 0x8) = 66048 {TCP:861, IPv4:843}

- SCCM server binds to SCMActivator and activates WMI component:

5877 14:42:47 05.09.2012 34.0610846 10.0.9.149 CLIENTNAME.company.com MSRPC MSRPC:c/o Bind: IRemoteSCMActivator(DCOM) UUID{000001A0-0000-0000-C000-000000000046} Call=0x3 Assoc Grp=0xBB15 Xmit=0x16D0 Recv=0x16D0 {MSRPC:865, TCP:861, IPv4:843}

5880 14:42:47 05.09.2012 34.0642128 CLIENTNAME.company.com 10.0.9.149 TCP TCP:Flags=...A...., SrcPort=DCE endpoint resolution(135), DstPort=51763, PayloadLen=0, Seq=1315818583, Ack=2250996747, Win=65535 (scale factor 0x0) = 65535 {TCP:861, IPv4:843}

5882 14:42:47 05.09.2012 34.0748352 CLIENTNAME.company.com 10.0.9.149 MSRPC MSRPC:c/o Bind Ack: Call=0x3 Assoc Grp=0xBB15 Xmit=0x16D0 Recv=0x16D0 {MSRPC:865, TCP:861, IPv4:843}

5883 14:42:47 05.09.2012 34.0750212 10.0.9.149 CLIENTNAME.company.com MSRPC MSRPC:c/o Alter Cont: IRemoteSCMActivator(DCOM) UUID{000001A0-0000-0000-C000-000000000046} Call=0x3 {MSRPC:865, TCP:861, IPv4:843}

5884 14:42:47 05.09.2012 34.0785470 CLIENTNAME.company.com 10.0.9.149 MSRPC MSRPC:c/o Alter Cont Resp: Call=0x3 Assoc Grp=0xBB15 Xmit=0x16D0 Recv=0x16D0 {MSRPC:865, TCP:861, IPv4:843}

5885 14:42:47 05.09.2012 34.0786863 10.0.9.149 CLIENTNAME.company.com DCOM DCOM:RemoteCreateInstance Request, DCOM Version=5.7 Causality Id={FEEE1975-B61E-42EB-B500-939EA5EE4B2A} {MSRPC:865, TCP:861, IPv4:843}

Frame: Number = 5885, Captured Frame Length = 923, MediaType = ETHERNET

+ Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-22-90-E3-B7-80],SourceAddress:[00-22-64-08-91-A6]

+ Ipv4: Src = 10.0.9.149, Dest = 10.102.0.230, Next Protocol = TCP, Packet ID = 639, Total IP Length = 909

+ Tcp: [Bad CheckSum]Flags=...AP..., SrcPort=51763, DstPort=DCE endpoint resolution(135), PayloadLen=869, Seq=2250996924 - 2250997793, Ack=1315818870, Win=257 (scale factor 0x8) = 65792

+ Msrpc: c/o Request: IRemoteSCMActivator(DCOM) {000001A0-0000-0000-C000-000000000046} Call=0x3 Opnum=0x4 Context=0x1 Hint=0x318

- DCOM: RemoteCreateInstance Request, DCOM Version=5.7 Causality Id={FEEE1975-B61E-42EB-B500-939EA5EE4B2A}

+ HeaderReq: DCOM Version=5.7 Causality Id={FEEE1975-B61E-42EB-B500-939EA5EE4B2A}

+ AggregationInterface: NULL

- ActivationProperties: OBJREFCUSTOM - {000001A2-0000-0000-C000-000000000046}

+ MInterfacePointerPtr: Pointer To 0x00020000

- Interface: OBJREFCUSTOM - {000001A2-0000-0000-C000-000000000046}

+ Size: 744 Elements

InterfaceSize: 744 (0x2E8)

- Interface: OBJREFCUSTOM - {000001A2-0000-0000-C000-000000000046}

Signature: 1464812877 (0x574F454D)

Flags: OBJREFCUSTOM - Represents a custom marshaled object reference

MarshaledInterfaceIID: {000001A2-0000-0000-C000-000000000046}

- Custom:

ClassId: {00000338-0000-0000-C000-000000000046}

ExtensionSize: 0 (0x0)

ObjectReferenceSize: 704 (0x2C0)

- ActivationProperties:

TotalSize: 688 (0x2B0)

Reserved: 0 (0x0)

+ CustomHeader:

- Properties: 6 Property Structures

+ Special:

- Instantiation:

+ Header:

InstantiatedObjectClsId: {8BC3F05E-D86B-11D0-A075-00C04FB68820} => This is WMI

ClassContext: 20 (0x14)

ActivationFlags: 2 (0x2)

FlagsSurrogate: 0 (0x0)

- Server responds with success and provides the endpoint information for WMI service:

5886 14:42:47 05.09.2012 34.0848992 CLIENTNAME.company.com 10.0.9.149 DCOM DCOM:RemoteCreateInstance Response, ORPCFLOCAL - Local call to this computer {MSRPC:865, TCP:861, IPv4:843}

- ScmReply:

+ Header:

+ Ptr: Pointer To NULL

+ RemoteReplyPtr: Pointer To 0x00106E98

- RemoteReply:

ObjectExporterId: 13300677357152346811 (0xB8957F961925A2BB)

+ OxidBindingsPtr: Pointer To 0x00102FF0

IRemUnknownInterfacePointerId: {0000B400-0580-0000-9A5E-C2357038B9DF}

AuthenticationHint: 4 (0x4)

+ Version: DCOM Version=5.7

- OxidBindings:

+ Size: 378 Elements

- Bindings:

WNumEntries: 378 (0x17A)

WSecurityOffsets: 263 (0x107)

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\PIPE\\atsvc]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\PIPE\\wkssvc]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\pipe\\keysvc]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\PIPE\\srvsvc]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\pipe\\trkwks]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\PIPE\\W32TIME]

- StringBindings:

TowerId: 15 (0xF)

NetworkAddress: \\\\CLIENTNAME[\\PIPE\\ROUTER]

- StringBindings:

TowerId: 7 (0x7)

NetworkAddress: CLIENTNAME[1431]

- StringBindings:

TowerId: 7 (0x7)

NetworkAddress: 10.102.0.230[1431]

Terminator1: 0 (0x0)

+ SecurityBindings:

Terminator2: 0 (0x0)

- Since WMI listens on TCP 1431, SCCM server tries to connect to that endpoint to access WMI subsystem:

...

8980 14:43:08 05.09.2012 55.1014127 10.0.9.149 CLIENTNAME.company.com TCP TCP: [Bad CheckSum]Flags=......S., SrcPort=51785, DstPort=1431, PayloadLen=0, Seq=1764982397, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:1203, IPv4:843}

9390 14:43:11 05.09.2012 58.1101896 10.0.9.149 CLIENTNAME.company.com TCP TCP:[SynReTransmit #8980] [Bad CheckSum]Flags=......S., SrcPort=51785, DstPort=1431, PayloadLen=0, Seq=1764982397, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:1203, IPv4:843}

11236 14:43:17 05.09.2012 64.1163158 10.0.9.149 CLIENTNAME.company.com TCP TCP:[SynReTransmit #8980] [Bad CheckSum]Flags=......S., SrcPort=51785, DstPort=1431, PayloadLen=0, Seq=1764982397, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:1203, IPv4:843}

- But this TCP session request fails because SCCM server doesn’t get a response to TCP SYN requests.

- When we check the client side network trace, we cannot see any of those TCP SYNs sent by the SCCM server.

This is most of the time a hardware router/firewall filtering problem. After our customer made the necessary configuration changes in the firewall, SCCM client push installation started working properly.

Since WMI is assigned a random TCP port from dynamic RPC port range at every startup, network/firewall administrators need to allow that range as well in addition to allowing TCP 135 activity towards the clients. One other alternative in this instance could be fixing the TCPIP port than WMI subsytem obtains at each startup. You can see the below article for more information on this:

http://support.microsoft.com/kb/897571 FIX: A DCOM static TCP endpoint is ignored when you configure the endpoint for WMI on a Windows Server 2003-based computer

Hope this helps

Thanks,

Murat

TMG Safe search feature may not work as expected sometimes

2013-01-06T14:50:00Z

In this post, I would like to talk about a TMG safe search problem which I dealt with recently. The problem was that the TMG safesearch feature wasn’t working properly even though the all the requirements were met. We decided to collect dynamic logs while reproducing the problem (TMG data packager + client side logs). Then I started analyzing the logs:

- The Safesearch related rule was already enabled:

SafeSearch Enabled

Action Allow

Applies Always true

Default false

Description The SafeSearch rule allows access to the "Search Engines" URL category, and filters out adult content from search results of supported search engines.

Logging Enabled

Source Port Limits Disabled

Type Access Rule

From

Network Internal, Included, Array scope

Applies to all content

Protocols Specified Protocols

HTTP, Included, Array scope

HTTPS, Included, Array scope

UrlCategory Search Engines, Included, Enterprise Scope

Users All Users, Included, Array scope

- It already included "All users"

- TMG server version was the latest (SP2 + rollup2)

- Safesearch XML file was in place with the correct settings:

</provider>

</provider>

</provider>

</Configuration>

- It's the same as the one provided in ISA blog:

http://blogs.technet.com/b/isablog/archive/2010/09/21/new-in-forefront-tmg-update-1-safesearch-enforcement.aspx

</provider>

=> Even though all configuration was correct, TMG server was still not forwarding the correct search URL towards Bing (which would help Bing filter search results)

- We see the search requests sent by the client on the client side network trace. Some examples:

2857 12:46:22.524738 50.167033 0.000000 10.96.96.6 10.110.0.121 HTTP GET http://www.bing.com/search?q=xxx&qs=n&form=QBLH&pq=xxx&sc=0-0&sp=-1&sk= HTTP/1.1

3642 12:46:44.659253 72.301548 0.054843 10.96.96.6 10.110.0.121 HTTP GET http://www.bing.com/images/search?q=xxx&FORM=HDRSC2 HTTP/1.1

3832 12:46:48.339288 75.981583 3.680035 10.96.96.6 10.110.0.121 HTTP GET http://www.bing.com/search?q=xxx&FORM=HDRSC1 HTTP/1.1

=> Relevant session in TMG ETL Logs: (collected as a result of TMG data packager)

...

[0]197c.1cc8 10/03/2012-10:46:48.780 [1a2c7b91 1a2c7d03] [WP proxyext...] Info: WPPISAPUBLIC:Context property:WPPISAPUBLIC:HTTP URL = http://www.bing.com/search?q=xxx&FORM=HDRSC1

...

=> Safesearch filter decides that there's no need for safesearch analysis:

[0]197c.1cc8 10/03/2012-10:46:48.781 [1a2c7b91 1a2c7d03] [HTTPFLT...] Entering CHttpFilterSafeSearchEnforcer::IsSafeSearchAnalysisRequired

...

[0]197c.1cc8 10/03/2012-10:46:48.781 [1a2c7b91 1a2c7d03] [HTTPFLT...] Info:SafeSearch analysis is not required, exiting

=> Network trace collected on the external interface of TMG server:

- We can see that the request is being sent as is without any modifications towards the Bing server:

256368 06:46:49.2700830 875.6370830 10.110.7.54 212.252.126.59 HTTP HTTP:Request, GET /search, Query:q=xxx&FORM=HDRSC1 {HTTP:3723, TCP:3721, IPv4:3651}

256370 06:46:49.3080860 875.6750860 212.252.126.59 10.110.7.54 TCP TCP:Flags=...A...., SrcPort=HTTP(80), DstPort=58199, PayloadLen=0, Seq=3768470858, Ack=3665294676, Win=25515 (scale factor 0x0) = 25515 {TCP:3721, IPv4:3651}

256372 06:46:49.3600890 875.7270890 212.252.126.59 10.110.7.54 HTTP HTTP:Response, HTTP/1.1, Status: Ok, URL: /search {HTTP:3723, TCP:3721, IPv4:3651}

http://www.bing.com/search?q=sex&FORM=HDRSC1

=> Normally it should have been sent something like below so that adult content wouldn't have been returned by Bing:

http://www.bing.com/search?q=sex&FORM=HDRSC1&adlt=strict

At this point everything seemed to be correctly configured but for some reason the safesearch filter wasn’t kicking in. After some more research and with the help of an escalation engineer from TMG team, we found out that in order for safesearch filter to kick in, the request itself also should be matching the Safesearch rule which is automatically created when Safesearch is enabled.

In my customer scenario, problem was that the access request sent by the user was hitting an enterprise level access rule and hence the safesearch rule wasn’t hit and the filter wasn’t activated as a result. After my customer re-arranged the enterprise level rules so that search engine related requests don’t hit any enterprise level access rule but hits the array level “Safesearch” rule created automatically, the problem was resolved.

Hope this helps

Thanks,

Murat

Slow performance when accessing a Sharepoint 2010 portal through an ISA 2006 array

2013-01-06T11:29:00Z

I was involved in a slow Sharepoint portal access through an ISA 2006 array problem and I wanted to talk about how I dealt with that issue and found the root cause of the slowness issue. The problem was that the portal home page was loaded very slowly and sometimes it wasn’ loaded at all from external clients. The performance was fine when it was accessed from internal clients

Our customer had a network setup similar to below:

We collected network traces from ISA servers while reproducing the problem. Network trace analysis revealed that ISA servers were responding to the requests immediately but there were delays in the incoming HTTP requests from the external clients and in some occasions external client didn’t complete the TCP three way handshake:

=> Examples of such huge gaps between requests from the external client seen in the network trace:

Note: 1.1.1.1 is the external client (real IP address was replaced)

Note: 192.168.1.36 is the web listener IP address to which sharepoint publishing rule is bound

17324 14:11:33.045375 11.859375 0.015625 1.1.1.1 192.168.1.36 HTTP GET /UserControls/TopMenu/TopMenu_Sep.gif HTTP/1.1
17326 14:11:33.045375 11.859375 0.000000 192.168.1.36 1.1.1.1 HTTP HTTP/1.1 304 Not Modified
17522 14:11:33.232875 12.046875 0.187500 1.1.1.1 192.168.1.36 HTTP GET /_layouts/1033/ie66up.js?rev=Ni7%2Fj2ZvA%33D HTTP/1.1
17524 14:11:33.232875 12.046875 0.000000 192.168.1.36 1.1.1.1 HTTP HTTP/1.1 304 Not Modified
17529 14:11:33.248500 12.062500 0.015625 1.1.1.1 192.168.1.36 TCP 1273 > 80 [ACK] Seq=2525698284 Ack=1206119216 Win=65664 Len=0
17533 14:11:33.264125 12.078125 0.015625 1.1.1.1 192.168.1.36 TCP 1269 > 80 [ACK] Seq=640090889 Ack=3984935419 Win=65340 Len=0
17593 14:11:33.451625 12.265625 0.187500 1.1.1.1 192.168.1.36 TCP 1268 > 80 [ACK] Seq=1670250900 Ack=2758693123 Win=65576 Len=0

There’s a huge time gap (around 83 seconds) in between the last response from the ISA server and the next request from the external client:

153758 14:12:56.998500 95.812500 83.546875 1.1.1.1 192.168.1.36 TCP 1268 > 80 [FIN, ACK] Seq=1670250900 Ack=2758693123 Win=65576 Len=0
153759 14:12:56.998500 95.812500 0.000000 192.168.1.36 1.1.1.1 TCP 80 > 1268 [ACK] Seq=2758693123 Ack=1670250901 Win=64684 [TCP CHECKSUM INCORRECT] Len=0
153760 14:12:56.998500 95.812500 0.000000 1.1.1.1 192.168.1.36 TCP 1269 > 80 [FIN, ACK] Seq=640090889 Ack=3984935419 Win=65340 Len=0
153761 14:12:56.998500 95.812500 0.000000 192.168.1.36 1.1.1.1 TCP 80 > 1269 [ACK] Seq=3984935419 Ack=640090890 Win=65535 [TCP CHECKSUM INCORRECT] Len=0
153762 14:12:56.998500 95.812500 0.000000 192.168.1.36 1.1.1.1 TCP 80 > 1268 [FIN, ACK] Seq=2758693123 Ack=1670250901 Win=64684 [TCP CHECKSUM INCORRECT] Len=0

...

158541 14:13:06.639125 105.453125 0.015625 192.168.1.36 1.1.1.1 HTTP HTTP/1.1 304 NOT MODIFIED
158576 14:13:06.842250 105.656250 0.203125 1.1.1.1 192.168.1.36 TCP 1290 > 80 [ACK] Seq=2442652609 Ack=3279316510 Win=65376 Len=0

Another time gap which is around 11 seconds in between the last response from the ISA server and the next request from the external client:

178031 14:13:18.014125 116.828125 11.171875 1.1.1.1 192.168.1.36 TCP 1292 > 80 [SYN] Seq=2506205172 Win=8192 Len=0 MSS=1380 WS=4 SACK_PERM=1
178032 14:13:18.014125 116.828125 0.000000 192.168.1.36 1.1.1.1 TCP 80 > 1292 [SYN, ACK] Seq=1749486699 Ack=2506205173 Win=16384 Len=0 MSS=1460 WS=1 SACK_PERM=1
178039 14:13:18.029750 116.843750 0.015625 1.1.1.1 192.168.1.36 TCP 1292 > 80 [ACK] Seq=2506205173 Ack=1749486700 Win=66240 Len=0
178042 14:13:18.029750 116.843750 0.000000 1.1.1.1 192.168.1.36 HTTP GET /Style%20Library/Images/leftCol_02.gif HTTP/1.1
178043 14:13:18.029750 116.843750 0.000000 192.168.1.36 1.1.1.1 HTTP HTTP/1.1 304 NOT MODIFIED
178202 14:13:18.248500 117.062500 0.218750 1.1.1.1 192.168.1.36 TCP 1292 > 80 [ACK] Seq=2506206023 Ack=1749486987 Win=65952 Len=0
255223 14:13:58.092250 156.906250 39.843750 1.1.1.1 192.168.1.36 TCP 1289 > 80 [RST, ACK] Seq=3712234005 Ack=2023647270 Win=0 Len=0

=> Another indication of a connectivity problem between the external client and the ISA 2006 server:

No. Time Time since Delta Source Destination Protocol Info
153775 14:12:57.014125 95.828125 0.000000 1.1.1.1 192.168.1.36 TCP 1288 > 80 [SYN] Seq=2013470292 Win=64860 Len=0 MSS=1380
153776 14:12:57.014125 95.828125 0.000000 192.168.1.36 1.1.1.1 TCP 80 > 1288 [SYN, ACK] Seq=535425124 Ack=2013470293 Win=16384 Len=0 MSS=1460
154809 14:12:59.342250 98.156250 2.328125 192.168.1.36 1.1.1.1 TCP 80 > 1288 [SYN, ACK] Seq=535425124 Ack=2013470293 Win=16384 Len=0 MSS=1460
158232 14:13:05.904750 104.718750 6.562500 192.168.1.36 1.1.1.1 TCP 80 > 1288 [SYN, ACK] Seq=535425124 Ack=2013470293 Win=16384 Len=0 MSS=1460

ISA receives TCP SYN from the external client and sends back a TCP SYN ACK immediately. Normally the client should have continued with a TCP ACK to finish the TCP 3-way handshake and then send the HTTP request on top of that TCP session but that doesn’t happen and ISA 2006 re-sends the TCP SYN ACK and resends one more time. For example this activity alone causes some 10 seconds to be lost.

Just to eliminate any network device issues we decided to access the same sharepoint portal just from the front of ISA array’s external interface (192.168.1.32/27 subnet) and the client was assigned an IP address from that subnet. After some testing from that client it was possible to quickly access the portal (and the test machine has no difference from an external client out in the internet from ISA perspective), it confirmed that the problem is not with ISA array but it’s a problem somewhere between ISA array’s external interface and our customer’s internet connection including the Cisco ASA device/internet routers.

Our customer’s network team was involved in and after the issue with the router/firewall was fixed, external clients also started accessing the portal very quickly.

Hope this helps

Thanks,

Murat

Direct access client fails to connect to UAG DA server through IPHTTPS with various errors (0x800b0109 and 0x274c)

2013-01-06T09:49:00Z

In this post, I want to talk about how I troubleshooted a direct access connectivity problem hoping that it might also help you in troubleshooting similar problems.

The issue was that the IPHTTPS client cannot connect to UAG DA server. We first checked static logs collected from a problem client (GPO output, firewall outputs, etc) and all seemed to be fine:

- Required services were running on the client (Windows Firewall/IKE and AuthIP/IP Helper)

- Firewall was chosing the correct firewall (Public profile):

-------------------------------------

netsh advfirewall show currentprofile

-------------------------------------

Public Profile Settings:

----------------------------------------------------------------------

State ON

Firewall Policy BlockInbound,AllowOutbound

LocalFirewallRules N/A (GPO-store only)

LocalConSecRules N/A (GPO-store only)

InboundUserNotification Enable

RemoteManagement Disable

UnicastResponseToMulticast Enable

Logging:

LogAllowedConnections Disable

LogDroppedConnections Disable

FileName C:\Windows\System32\LogFiles\Firewall\pfirewall.log

MaxFileSize 4096

Ok.

- All categories including connection security was owned by Windows Firewall:

Categories:

BootTimeRuleCategory Windows Firewall

FirewallRuleCategory Windows Firewall

StealthRuleCategory Windows Firewall

ConSecRuleRuleCategory Windows Firewall

- gpresult output collected confirmed that the client was getting the required policy which is UAG DirectAccess: Clients (UAGServer-FQDN)

Then I asked our customer to implement the below action plan to collect dynamic data while reproducing the problem

Action plan for log collection:

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

The outline of the action plan is below:

- Start WFP/DirectAccess/network traces on the DA client

- Start WFP/DirectAccess/network traces on the UAG DA server

- Stop and restart the relevant services (like IKE/ip helper) to trigger the tunnel establishment and see things from scratch

- Once we observe that the client cannot access any internal resources we’ll stop logs on the DA client and UAG DA server

1) Please install Network Monitor 3.4 on a problem DA client and on the UAG DA server. You can download the tool at the following link:

http://www.microsoft.com/downloads/details.aspx?displaylang=en&FamilyID=983b941d-06cb-4658-b7f6-3088333d062f

2) Please disable and stop “IKE and AuthIP IPSec Keying Modules” service with the below commands on the DA client:

Note: All commands need to be run from an elevated command prompt.

a) We first disable the service:

sc config ikeext start= disabled

(Note: There must be a SPACE between “=” and “disabled”, otherwise the command doesn’t work)

b) We stop the service:

net stop ikeext

3) Now we start the network capture on the DA client and on the UAG server: (from an elevated command prompt)

=> On the DA client:

nmcap /network * /capture /file DAClient.chn:100M

=> On the UAG DA server:

nmcap /network * /capture /file DAServer.chn:100M

Note: You have to run the nmcap command from an elevated command prompt on Windows Vista/Windows 7/Windows 2008/Windows 2008 R2

Note: nmcap will create a new capture file once the first one if full (200 MB) and so on. So please make sure that you have enough free disk space on the related drive.

Note: If you get the error message "'nmcap' is not recognized as an internal or external command, operable program or batch file", you may need to run the nmcap command inside "%ProgramFiles%\Microsoft Network Monitor 3" folder

Note: Network trace could be stopped any time by pressing Ctrl + C

4) Let’s start tracing for various components at a different elevated command prompt on the DA client and on the UAG DA server:

=> On the DA client:

netsh wfp capture start

netsh trace start scenario=directaccess provider=microsoft-windows-iphlpsvc level=5 capture=yes tracefile=darepro.etl maxsize=350

=> On the UAG DA server:

netsh wfp capture start

netsh trace start provider=Microsoft-Windows-DNS-Client provider=Microsoft-Windows-Iphlpsvc-Trace provider=Microsoft-Windows-WFP provider=Microsoft-Windows-NCSI provider=Microsoft-Windows-NlaSvc provider=Microsoft-Windows-NetworkProfile provider=Microsoft-Windows-WinINet provider=Microsoft-Windows-WinHttp provider=Microsoft-Windows-WebIO provider="Microsoft-Windows-Windows Firewall With Advanced Security" tracefile=c:\logs\UAGDAServer.etl maxsize=400

5) Now we’re going to reproduce the problem from the DA client side.We’re going to stop iphlpsvc on the DA client: (the service which implements the IPv6 transition technologies)

net stop iphlpsvc

6) Just before we start re-enabling the relevant services on the DA client, we run the following ping on the DA client: (with 22 bytes ping)

ping -l 22 -n 2 IP-address-of-default-gateway-configured-on-the-client

Note: Please replace IP-address-of-default-gateway-configured-on-the-client with the real default gateway address configured on the client

7) Now please run the following commands in the given order on the DA client:

net start iphlpsvc

sc config ikeext start= auto

net start ikeext

(Note: There must be a SPACE between “=” and “disabled” in "sc config" command, otherwise the command doesn’t work)

8) Let’s please wait for 30 seconds or so and then try the following commands on the DA client:

ping -l 33 an-internal-server1

ping -l 44 an-internal-server2

net view \\an-internal-server1

net view \\an-internal-server2

As an additional test, you can try to reach an internal web server/sharepoint portal etc if any exists from Internet explorer on the DA client (like accessing http://internalserver3/portal)

NOTE: Please replace the “an-internal-server” with real ones

NOTE: Please write down the full commands that you run

NOTE: Please take a screenshot of each access attempts

9) After you get errors for the above commands, please run the following commands (all from an elevated command prompt) on the DA client and on the UAG DA server to stop the logs running:

=> On the UAG DA server:

a) To stop WFP tracing:

netsh wfp capture stop

b) To stop Directaccess tracing:

netsh trace stop

c) To stop Network trace on the UAG DA server:

Please hit CTRL+C at the command prompt where nmcap tool runs

=> On the DA client:

a) To mark the end of problem reproduce (with 55 bytes ping)

ping -l 55 -n 2 IP-address-of-default-gateway-configured-on-the-client

b) To stop WFP tracing:

netsh wfp capture stop

c) To stop Directaccess tracing:

netsh trace stop

d) To stop Network trace on the DA client:

Please hit CTRL+C at the command prompt where nmcap tool runs

ANALYSIS 1:

==========

After analyzing the logs collected as per the above action plan, I got the following findings:

=> IPHTTPS interafce was not connected with the error number 0x800b0109

Interface IPHTTPSInterface (Group Policy) Parameters

------------------------------------------------------------

Role : client

URL : https://UAGDAServer-FQDN:443/IPHTTPS

Last Error Code : 0x800b0109

Interface Status : failed to connect to the IPHTTPS server. Waiting to reconnect

err 0x800b0109

# for hex 0x800b0109 / decimal -2146762487 :

CERT_E_UNTRUSTEDROOT winerror.h

# A certificate chain processed, but terminated in a root

# certificate which is not trusted by the trust provider.

# 1 matches found for "0x800b0109"

=> IPHTTPS client doesn’t accept the certificate provided because it doesn’t trust the issuer

=> When I checked the network activity, I saw the following communications:

2084 15:13:43.441664 463.087187 0.002359 192.168.99.5 192.168.99.100 DNS Standard query A UAGDAServer-FQDN

2085 15:13:43.442251 463.087774 0.000587 192.168.99.100 192.168.99.5 DNS Standard query response A 1.1.1.2

Now client tries to establish the TLS tunnel:

No. Time Time since Delta Source Destination Protocol Identification S-Port D-Port Sequence TCP Len TCP Ack TCP Win Info

2086 15:13:43.443150 463.088673 0.000000 192.168.99.5 1.1.1.2 TCP 0x58ba (22714) 57134 443 1683802426 0 8192 57134 > 443 [SYN] Seq=1683802426 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 WS=256 SACK_PERM=1

2087 15:13:43.479192 463.124715 0.036042 1.1.1.2 192.168.99.5 TCP 0x61f4 (25076) 443 57134 536292141 0 1683802427 8192 443 > 57134 [SYN, ACK] Seq=536292141 Ack=1683802427 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

2088 15:13:43.479356 463.124879 0.000164 192.168.99.5 1.1.1.2 TCP 0x58bb (22715) 57134 443 1683802427 0 536292142 65536 57134 > 443 [ACK] Seq=1683802427 Ack=536292142 Win=65536 [TCP CHECKSUM INCORRECT] Len=0

2089 15:13:43.491000 463.136523 0.011644 192.168.99.5 1.1.1.2 TLSv1 0x58bc (22716) 57134 443 1683802427 119 536292142 65536 Client Hello

2092 15:13:43.530437 463.175960 0.039437 1.1.1.2 192.168.99.5 TLSv1 0x61f5 (25077) 443 57134 536292142 853 1683802546 65536 Server Hello, Certificate, Server Key Exchange, Server Hello Done

2093 15:13:43.569422 463.214945 0.038985 192.168.99.5 1.1.1.2 TLSv1 0x58be (22718) 57134 443 1683802546 134 536292995 64768 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message

Certificate (id-at-commonName=Default Web Site) => Returned certificate is not the one expected by the client

2094 15:13:43.608227 463.253750 0.038805 1.1.1.2 192.168.99.5 TLSv1 0x61f6 (25078) 443 57134 536292995 59 1683802680 65536 Change Cipher Spec, Encrypted Handshake Message

2095 15:13:43.608869 463.254392 0.000642 192.168.99.5 1.1.1.2 TCP 0x58bf (22719) 57134 443 1683802680 0 536293054 64768 57134 > 443 [FIN, ACK] Seq=1683802680 Ack=536293054 Win=64768 [TCP CHECKSUM INCORRECT] Len=0

2096 15:13:43.645152 463.290675 0.036283 1.1.1.2 192.168.99.5 TCP 0x61f7 (25079) 443 57134 536293054 0 1683802681 0 443 > 57134 [RST, ACK] Seq=536293054 Ack=1683802681 Win=0 Len=0

=> On the other hand when checking the certificate bindings on the UAG server side, I saw that UAG DA server IPHTTPS server was bound to 1.1.1.1:443 with the appropriate certificate

c:\> netsh http show sslcert

...

IP:port : 1.1.1.1:443

Certificate Hash : 8691087835614a5f09b5f11c403d595c461ff603

Application ID : {5d8e2743-ef20-4d38-8751-7e400f200e65}

Certificate Store Name : MY

Verify Client Certificate Revocation : Enabled

Verify Revocation Using Cached Client Certificate Only : Disabled

Usage Check : Enabled

Revocation Freshness Time : 0

URL Retrieval Timeout : 0

Ctl Identifier :

Ctl Store Name :

DS Mapper Usage : Enabled

Negotiate Client Certificate : Disabled

...

c:\> certutil -store -v my

...

================ Certificate 2 ================

Serial Number: 5485200900020000015c

Issuer: CN=CA-name, DC=company, DC=com

NotBefore: 18/04/2012 16:49

NotAfter: 18/04/2014 16:49

Subject: CN=UAGDAServer-FQDN

Non-root Certificate

Template: WebServer3, Web Server 3

Cert Hash(sha1): 86 91 08 78 35 61 4a 5f 09 b5 f1 1c 40 3d 59 5c 46 1f f6 03

Key Container = d53d6468acfdb333ca5698ae67f3549e_6dd37665-5fa6-46ec-89de-8857879f2500

Simple container name: le-WebServer3-afc38199-0bb5-4cb9-b043-50851171183d

Provider = Microsoft Base Cryptographic Provider v1.0

Encryption test passed

...

The certificate seems to be the correct one but since UAGDAServer-FQDN is not mapped to 1.1.1.1 (it’s mapped to 1.1.1.2), another certificate is returned to the client in the TLS sessions and IPHTTPS connection fails as well. That was also evident in the network trace:

2084 15:13:43.441664 463.087187 0.002359 192.168.99.5 192.168.99.100 DNS Standard query A UAGDAServer-FQDN

2085 15:13:43.442251 463.087774 0.000587 192.168.99.100 192.168.99.5 DNS Standard query response A 1.1.1.2

I informed my customer about the problem and they changed the DNS settings. But afterwards my customer informed me that IPHTTPS connectivity problem was still in place but this time with a different error number. We re-run the previous action plan and collected logs one more time:

ANALYSIS 2:

=========

This time the problem was a bit different. As per the log outputs from the client and UAG DA server, there was a packet drop issue between the client and server, client’s IPHTTPS traffic wasn’t arriving at UAG DA server so the IPHTTPS tunnel establishment was failing:

c:\> netsh interface httpstunnel show interface

Interface IPHTTPSInterface (Group Policy) Parameters

------------------------------------------------------------

Role : client

URL : https://UAGDAServer-FQDN:443/IPHTTPS

Last Error Code : 0x274c

Interface Status : failed to connect to the IPHTTPS server. Waiting to reconnect

err 0x274c

# for hex 0x274c / decimal 10060 :

WSAETIMEDOUT winerror.h

# A connection attempt failed because the connected party did

# not properly respond after a period of time, or established

# connection failed because connected host has failed to

# respond.

WSAETIMEDOUT winsock2.h

# 2 matches found for "0x274c"

=> And we can really see that the DA client could not connect to TCP 443:

No. Time Time since Delta Source Destination Protocol Info

2657 14:43:33.170638 199.176755 197.498302 192.168.99.7 1.1.1.1 TCP 54007 > 443 [SYN] Seq=2446300399 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

2693 14:43:33.563827 199.569944 0.393189 192.168.99.7 1.1.1.1 TCP 54008 > 443 [SYN] Seq=4024014335 Win=8192 Len=0 MSS=1460 SACK_PERM=1

2736 14:43:36.583165 202.589282 0.258635 192.168.99.7 1.1.1.1 TCP 54008 > 443 [SYN] Seq=4024014335 Win=8192 Len=0 MSS=1460 SACK_PERM=1

2839 14:43:42.577128 208.583245 0.259486 192.168.99.7 1.1.1.1 TCP 54008 > 443 [SYN] Seq=4024014335 Win=8192 Len=0 MSS=1460 SACK_PERM=1

3482 14:44:24.615646 250.621763 18.289976 192.168.99.7 1.1.1.1 TCP 54023 > 443 [SYN] Seq=3215921282 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

3516 14:44:27.621705 253.627822 3.006059 192.168.99.7 1.1.1.1 TCP 54023 > 443 [SYN] Seq=3215921282 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

3585 14:44:33.627033 259.633150 6.005328 192.168.99.7 1.1.1.1 TCP 54023 > 443 [SYN] Seq=3215921282 Win=8192 Len=0 MSS=1460 SACK_PERM=1

4432 14:45:36.642904 322.649021 4.472205 192.168.99.7 1.1.1.1 TCP 54035 > 443 [SYN] Seq=55761659 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

4472 14:45:39.638130 325.644247 2.995226 192.168.99.7 1.1.1.1 TCP 54035 > 443 [SYN] Seq=55761659 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

4539 14:45:45.653327 331.659444 6.015197 192.168.99.7 1.1.1.1 TCP 54035 > 443 [SYN] Seq=55761659 Win=8192 Len=0 MSS=1460 SACK_PERM=1

6202 14:48:00.662720 466.668837 41.395992 192.168.99.7 1.1.1.1 TCP 54064 > 443 [SYN] Seq=2998968172 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

6239 14:48:03.672009 469.678126 3.009289 192.168.99.7 1.1.1.1 TCP 54064 > 443 [SYN] Seq=2998968172 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

6309 14:48:09.673882 475.679999 6.001873 192.168.99.7 1.1.1.1 TCP 54064 > 443 [SYN] Seq=2998968172 Win=8192 Len=0 MSS=1460 SACK_PERM=1

=> Also none of the above requests seen on the client side trace were present on the UAG DA server side trace which meant that UAG DA server never saw them

My customer further checked the connectivity with their service provider and it was found out that due to an incorrect routing configuration traffic sent to 1.1.1.1:443 was really dropped/routed somewhere else and hence the IPHTTPS tunnel wasn’t established. After fixing the issue with the router configuration, the problem was resolved and IPHTTPS tunnel was successfully established.

Hope this helps

Thanks,

Murat

TCP delayed ACK combined with Nagle algorithm can badly impact communication performance

2013-01-05T16:21:00Z

Recently I was involved in a network connectivity performance issue and wanted to share the root cause we found. You can find below an example communication of how the slow performance occurs:

10.15.28.40: A Windows application server

10.95.2.49: A UNIX application server

No. Time Delta Source Destination Protocol Length Info

3562 2012-12-12 18:19:53.258784 0.000000 10.15.28.40 10.95.2.40 TCP 377 51122 > 7890 [PSH, ACK] Seq=2654579738 Ack=1586267028 Win=253 Len=323

3563 2012-12-12 18:19:53.359881 0.101097 10.95.2.40 10.15.28.40 TCP 60 7890 > 51122 [ACK] Seq=1586267028 Ack=2654580061 Win=49640 Len=0

3564 2012-12-12 18:19:53.359939 0.000058 10.95.2.40 10.15.28.40 TCP 60 7890 > 51122 [PSH, ACK] Seq=1586267028 Ack=2654580061 Win=49640 Len=6

3566 2012-12-12 18:19:53.550528 0.190589 10.15.28.40 10.95.2.40 TCP 54 51122 > 7890 [ACK] Seq=2654580061 Ack=1586267034 Win=253 Len=0

3567 2012-12-12 18:19:53.551151 0.000623 10.95.2.40 10.15.28.40 TCP 330 7890 > 51122 [PSH, ACK] Seq=1586267034 Ack=2654580061 Win=49640 Len=276

3585 2012-12-12 18:19:53.753770 0.202619 10.15.28.40 10.95.2.40 TCP 54 51122 > 7890 [ACK] Seq=2654580061 Ack=1586267310 Win=252 Len=0

At frame #3562, Windows Application server sends a request to the UNIX application server

At frame #3563, UNIX server sends an ACK back to Windows server (probably the current TCP delayed ACK timer on UNIX server side is around 100 msec)

At frame #3564, shortly after the delayed ACK, UNIX applications first response packet is received (6 bytes - probably the application sends the application layer protocol header and payload seperately) that it delayed until it receives an ACK from the other party.

At frame #3566, TCP delayed ACK timer on Windows application server expires (which is around ~200 msec) and then Windows sends a delayed ACK back to UNIX server. The reason delayed ACK timer expires on Windows server is that it receives a TCP segment from UNIX server but it doesn’t receive any other segments.

At frame #3567, UNIX application server sends the rest of the application layer data after the ACK is received

The reason Windows waits for ~200 msec at frame #3566 is TCP delayed ACK mechanism. The reason UNIX application layer server doesn’t send the 6 bytes or 276 bytes payloads until the previous TCP segment (6 bytes) it sent was ACKed is Nagle algorithm.

As you can see above, TCP delayed ACK + Nagle + application behavior bring some ~100 msec + ~200 msec = ~300 msec average delay in every transaction. Considering that thousands of transactions take place for the duration of the session between the two application servers cause a considerable amount of delay.

The solution here was to turn off TCP delayed ACK on Windows server side since it was the easiest one to implement in customer’s scenario. Another option could be turning Nagle algorithm off on the UNIX side application server which serves the application running on Windows.

The following Wikipedia article also summarizes the Nagle algorithm:

This algorithm interacts badly with TCP delayed acknowledgments, a feature introduced into TCP at roughly the same time in the early 1980s, but by a different group. With both algorithms enabled, applications that do two successive writes to a TCP connection, followed by a read that will not be fulfilled until after the data from the second write has reached the destination, experience a constant delay of up to 500 milliseconds, the "ACK delay". For this reason, TCP implementations usually provide applications with an interface to disable the Nagle algorithm. This is typically called the TCP_NODELAY option.

If possible an application should avoid consecutive small writes in the first place, so that Nagle's algorithm will not be triggered. The application should keep from sending small single writes and buffer up application writes then send (or with the help of writev() call).

What we were observing was exactly the same mentioned above. You can also find more information on how to turn off TCP Delayed ACK on Windows servers by changing the TcpAckFrequency registry key:

http://support.microsoft.com/kb/823764 Slow performance occurs when you copy data to a TCP server by using a Windows Sockets API program

Hope this helps

Thanks,

Murat

Network trace analysis tricks III - How can I comment on packets in a network trace

2012-07-11T16:08:00Z

After you get familiar with using protocol analysis tools like Network Monitor or Wireshark, you’ll get to the most important stage in network trace analysis: How can I comment on packets sent or received in a network trace? Was it normal to see that packet being sent or received? What packet should I have seen after this one under normal circumstances? You can increase the number of such questions very quickly…

As you can imagine, you have to know the mechanics of each protocol that you’re dealing with in a network trace. There are so many network protocols that it makes it unlikely that you can be familiar with all of them. But at least you should be able to comment on general network protocols and application layer protocols that you’re mostly dealing with.

The following are the most important general network protocols (most of them run at lower layers) that you need to be familiar with:

- Ethernet

- ARP

- IPv4 / IPv6

- ICMPv4 / ICMPv6

- TCP

- UDP

- DNS

- NBNS

- DHCP

The following general application layer protocols are the ones that you’ll come across very oftenly in network traces:

- HTTP

- FTP

- SSL / TLS

- NetBT

- SMB (v2/v3)

- DFS

- DCERPC

- LDAP

- Kerberos

- SIP

- RTP / RTCP

- PPTP

- L2TP / IPSec

- TDS

- RDP

There are also many Microsoft specific application layer protocols that typically run over DCERPC and provide remote services (like Eventlog remoting, printing, DCOM, WMI, DHCP management protocol, DNS management protocol, certificate services management protocol, AD management protocols, Exchange protocols so on and so forth) you might see in network traces.

As mentioned above, there’re so many of them J As a Microsoft support engineer, I come across most of them when analyzing network traces but one could hardly master all such protocols. You become more familiar with some of them over time based on the problems you deal with. But I should definitely state that it’s a must to know about the general network procotols. (especially ARP/IP/TCP/ICMP/UDP)

There’re so many references in the internet so you shouldn’t have any problems in finding out information on a given protocol (unless it’s a proprietary protocol). Also another way of getting familiar with such protocols is to fiddle with them as much as possible. For example, when I want to learn what is going on behind the scenes when I take a specific action in an application/services, I collect a network trace and try to decode the activity taking place on the wire. That also helps you understand how a certain application makes it way through the network even you don’t know much about that application.

Having said that, let me share some links for more detailed information on protocols:

=> You can find detailed information on Microsoft protocols at the following link:

http://msdn.microsoft.com/en-us/library/cc216513(v=prot.10).aspx Windows Communication Protocols (MCPP)

=> Other standard protocols:

- You might want to check RFCs for the other standard protocols. Please see below a few examples:

http://www.faqs.org/rfcs/rfc826.html An Ethernet Address Resolution Protocol

http://www.faqs.org/rfcs/rfc791.html Internet Protocol (IPv4)

http://www.faqs.org/rfcs/rfc2460.html Internet Protocol, Version 6 (IPv6) Specification

http://www.faqs.org/rfcs/rfc793.html Transmission Control Protocol

http://www.faqs.org/rfcs/rfc2616.html Hypertext Transfer Protocol -- HTTP/1.1

http://www.faqs.org/rfcs/rfc959.html File Transfer Protocol

http://www.faqs.org/rfcs/rfc1541.html Dynamic Host Configuration Protocol

http://www.faqs.org/rfcs/rfc1034.html DOMAIN NAMES - CONCEPTS AND FACILITIES

http://www.faqs.org/rfcs/rfc2251.html Lightweight Directory Access Protocol (v3)

http://www.faqs.org/rfcs/rfc1510.html The Kerberos Network Authentication Service (V5)

…

Hope this helps

Thanks,

Murat

Network trace analysis tricks II - How can I focus on a certain packet range in a network trace?

2012-06-27T14:51:00Z

In the second post of “network analysis tricks” series, I’ll explain how to focus on a certain range of packets in a network trace.

When I ask for a network trace from a customer, I almost always ask for ICMP markers before and after reproducing the problem. You can see an example action plan below to see what I mean:

<<Start network trace on the client>>
ping -l 22 -n 1 IP-address-of-default-gateway
<<Reproduce the problem now. Example: Try to connect to www.microsoft.com from IE and once you get the “page not found” run the second ping>>
ping -l 33 -n 1 IP-address-of-default-gateway
<<Stop network trace on the client>>

Note: You can check the following blog post for more information about general network trace collection tricks

http://blogs.technet.com/b/nettracer/archive/2012/06/22/network-traffic-capturing-hints.aspx

In our example, when the network trace is collected as per the above action plan, it’s very clear that we will only be focusing on packets that were received/sent between 22 bytes and 33 bytes ICMP packets sent to the default gateway and we will safely ignore packets before 22 bytes ICMP packet or packets after 33 bytes ICMP packet. So if the 22 bytes and 33 bytes ICMP requests and responses are as given below:

Packet1

Packet2

Packet3

Packet4

Packet5

Packet6 <<22 bytes ICMP echo request>>

Packet7

Packet8

Packet9 <<22 bytes ICMP echo response>>

Packet10

Packet11

Packet12

Packet13

Packet14

Packet15

Packet16

Packet17

Packet18

Packet19

Packet20 <<33 bytes ICMP echo request>>

Packet21

Packet22

Packet23 <<33 bytes ICMP echo request>>

Packet24

Packet25

Packet26

Packet27

…

it will mean we will only need to focus on packets between packet10 and packet19 and can safely ignore all packets after packet19 or all packets before packet10.

You might be wondering how you can identify those 22 bytes or 33 bytes ICMP packets in a network trace. It’s fairly simple, we filter the network trace based on icmp protocol and ip packet length. For example the following Wireshark filter will show us all ICMP packets whose payloads are 22 bytes or 33 bytes:

icmp and (ip.len==50 or ip.len==61)

=> Total length in IP header is set to 50 when we send a 22 bytes ping request:

20 bytes IP header + 8 bytes ICMP header + 22 bytes ICMP payload

=> Total length in IP header is set to 61 when we send a 33 bytes ping request:

20 bytes IP header + 8 bytes ICMP header + 33 bytes ICMP payload

Example:

That would mean that we need to focus on frames between frame #126 and frame #210 since we reproduced the problem between 22 bytes and 33 bytes pings as given below:

Of course we’ll need to do further filtering based on the problem we’re troubleshooting, but for now we managed to isolate the traffic that we need to analyze to a certain range.

From this point on, whatever filter we apply to the network trace, we can put the following filter in front of it:

frame.number>=126 and frame.number<=210

Let’s say that we troubleshoot a TCP connection problem to TCP port 389 in this network trace. Then we can simply apply the following filter (in Wireshark):

as we won’t be interested in any packets sent/received to TCP port 389 before frame#126 or after frame#210 (because those frames are sent/received before we reproduce the problem and after we reproduce the problem)

Hope this helps

Thanks,

Murat

Network trace analysis tricks I - How can I see all TCP connection attempts in a network trace?

2012-06-22T14:27:00Z

In the “network analysis tricks” series of posts, I’ll try to explain some techniques that I use when analyzing network traces.

In this first post, I would like to explain how I find all TCP connection attempts in a network trace.

To see all TCP connection attempts in a network trace, you can use the following filter: (applies to both Network Monitor and Wireshark)

tcp.flags.syn==1

Network Monitor output:

Wireshark output:

After we apply the filter, we see that 10.1.1.4 tries to open different TCP sessions to 10.1.1.3 at TCP port 135, 1064, 3028 and 3029. Please note that the filter only displays the first two packets of each TCP session because only the first two TCP segments have the SYN flag set to 1. After finding out the TCP sessions, you can see the whole TCP session with a new filter.

For example, if we need to see the all TCP packets in the TCP session between 10.1.1.4:3026 <--> 10.1.1.3:135, we can apply the following filter and see all the packets exchanged in that session:

You can extend the filter to limit the output. Please see some examples below:

=> This filter will show all TCP connection attempts to TCP port 80 (HTTP)

tcp.flags.syn==1 and tcp.port==80

=> This filter will show all TCP connection attempts to TCP port 80 (HTTP) between 10.1.1.3 and 10.1.1.4

tcp.flags.syn==1 and tcp.port==80 and ip.addr==10.1.1.3 and ip.addr==10.1.1.4 (for Wireshark)

tcp.flags.syn==1 and tcp.port==80 and ip.addr==10.1.1.3 and ip.addr==10.1.1.4 (for Network monitor)

If you would like to see all TCP sessions ongoing in a network trace (not just the ones that was established within the timeframe covered by the trace) with some useful information, you can use a nice Wireshark feature called “Conversations”.

You first need to select "Conversations" from "Statistics" menu in Wireshark:

Then you need to click on "TCP" tab in the "Conversations" window

So we can see the same four TCP sessions that were seen with the previous filter. On top of that we can see many details for each session like how many packets/bytes were exchanged in each direction, the duration of a given TCP session seen in the trace, and approximate bandwidth usage of a given TCP session.

When troubleshooting network connectivity/performance problems, I very oftenly use the above techniques to find out different TCP sessions because an application/service might try to establish multiple TCP sessions when doing its work.

Hope this helps

Thanks,

Murat

Network traffic capturing hints

2012-06-22T12:23:00Z

In this post, I would like to talk about some important points about network capturing. If a network trace is not collected appropriately, it won’t provide any useful information and it will be a waste of time analyzing such a network trace.

Additionally, just collecting the network trace isn’t sufficient if you intend to ask for some help when analyzing that network trace, you also have to provide some information about the trace itself. Generally I collaborate with other colleagues in terms of network trace analysis and I have a standard template of questions when I’m approached by a colleague for assistance in analyzing a network trace:

- What is the exact problem definition

- Which network traces were collected on which system

- The IP addresses of the relevant systems (like client/server/DC/DNS)

- OS versions for relevant systems

- Network topology between the source and target systems on which network traces were collected

- The exact date & time of the problem & error seen

- The exact error message seen

- What were the exact actions taken when collecting the network traces (as much detailed as possible)

Now let’s talk about some important points that we need to be aware of to be able to collect a useable network trace that will really help you troubleshoot a given problem.

1) First of all, we need to make sure that it really makes sense to collect a network trace for the problem in hand. You can check the previous blog post to have a better idea on this:

http://blogs.technet.com/b/nettracer/archive/2012/06/22/when-do-we-need-collect-network-traces.aspx

2) Especially in switched networks, when we collect a network trace from a given node (a client or server), only the following traffic will be seen by the capturing agent (like Network monitor/Wireshark/...) running on the node:

- Packets sent out by the node itself

- Packets sent to the node’s unicast address

- Packets sent to unknown unicast addresses (switch doesn’t have that MAC address at its MAC address table yet so it floods the frame everywhere)

- Packets sent to broadcast address

- Packets sent to multicast addresses

So we won’t be able to see the packets sent to/received from client2 in a network trace collected on client1. If you really have to see the packets sent to/received from a node other than the node on which network trace is collected, you have to do port mirroring configuration (and your LAN switch should support it as well). Most of the LAN switches used in enterprise networks support port mirroring. You can see below a link for making such a configuration on Cisco LAN switches:

http://www.cisco.com/en/US/products/hw/switches/ps708/products_tech_note09186a008015c612.shtml

Switched Port Analyzer (SPAN) Configuration Example

3) If you troubleshoot a communication or performance problem between two processes running on the same node, that traffic won’t leave the machine and hence the network traffic won’t be captured by the capturing agent (Network Monitor/Wireshark). The traffic will be looped back by TCPIP stack. As an example, you won’t be able to see the network activity taking place between Internet Explorer and the Web server running on the same machine. If you need to troubleshoot such a scenario, you might try to collect an ETL trace, but the node will have to be running Windows 7 or Windows 2008 R2 for that. Please see the following post for more details on collecting such an ETL trace:

http://blogs.technet.com/b/nettracer/archive/2010/10/06/how-it-works-under-the-hood-a-closer-look-at-tcpip-and-winsock-etl-tracing-on-windows-7-and-windows-2008-r2-with-an-example.aspx

4) When collecting a network trace from a busy server, a capture filter might be applied to minimize the amount of traffic captured. We generally don’t prefer to capturing network traffic with a capture filter because when such a capture filter is applied, we take the risk of excluding some of the traffic that might be really relevant to the issue. If you’re really sure about what you have to check, then you may want to apply such a filter. You can find below an example of capturing with a filter with nmcap (command line version of Network monitor)

Note: The following is taken from nmcap /examples output:

This example starts capturing network frames that DO NOT contain ARPs, ICMP, NBtNs and BROWSER frames. If you want to stop capturing, Press Control+C.

nmcap /network * /capture (!ARP AND !ICMP AND !NBTNS AND !BROWSER) /File NoNoise.cap

5) If you really need to capture network traffic from a very busy server and you don’t want to take the risk of excluding some network traffic that might be relevant, you might want to capture let’s say only the first 256 bytes of each packets. Considering that a standard ethernet frame is about 1500 bytes, this will provide you a saving of ~%80. You can find an example for nmcap where only the first 256 bytes of each packet is captured:

nmcap /network * /MaxFrameLength 256

6) If network traces will be collected for an extended period, capturing all packets inside the same file will make it nearly impossible to analyze it (example: 5 GB network trace). To be able to collect manageable and analyzable network traces, it’s suggested to collect chained and fragmented network traces. You can find below an example for nmcap again:

nmcap /network * /capture /file ServerTest.chn:200M

Note: nmcap will create a new capture file once the first one if full (200 MB) and so on. So please make sure that you have enough free disk space on the related drive.

Note: The traces created will be named as ServerTest.cap, ServerTest(1).cap, ServerTest(2).cap,...

7) If you have to collect network traces for an unspecified period of time and you would like to see some activity taking place some time before the problem, you may have to collect network traces in a circular fashion which is possible with dumpcap (command line version of Wireshark for trace collection). You can see an example below:

dumpcap -i 2 -w c:\traces\servername.pcap -b filesize:204800 -b files:80

Notes 1: interface id "2" will be monitored and each capture file will be 204800 KB (200 MB)

Notes 2: The command assumes that c:\traces folder already exists. Also please make sure that there's enough free space on that drive (C: in this instance). 16 GB's of free space will be required to create and save 80 x 200 MB traces.

Notes 3: Eighty different files will be created with "servername_0000n_Date&time.pcap" syntax.

Example:

servername_00001_20120622134811.pcap

servername_00002_20120622135617.pcap

servername_00003_20120622141512.pcap

Notes 4: When all eighty files are created and full, it will start overwriting starting from the oldest trace file

Notes 5: Trace could be stopped any time by pressing Ctrl+C

8) It’s important to mark network traces with pings to be able to narrow down the time period that you need focus on in the trace. For example, you can ping the default gateway of the client just before and right after reproducing the problem.

Example1:

<<Start network trace on the client>>

ping -l 22 -n 2 IP-address-of-default-gateway

<<Reproduce the problem now. Example: Try to connect to www.microsoft.com from IE and once you get the “page not found” run the second ping>>

ping -l 33 -n 2 IP-address-of-default-gateway

<<Stop network trace on the client>>

Example2:

<<Start network trace on the client>>

ping -l 22 -n 5 IP-address-of-the-file-server

start > run > \\server\share

<<assuming that it takes 5+ seconds to open up the share content. Once the share content is listed, please run the below command>>

ping -l 33 -n 5 IP-address-of-the-file-server

<<Please write down the following information : the exact date&time of this test / how long it took to display the share content / exact \\server\share that you accessed >>

dir \\server\share

<<Please write down the following information : how long it took to display the share content when you used "dir" command>>

ping -l 44 -n 5 IP-address-of-the-file-server

<<Stop network trace on the client>>

When you start analyzing a network trace collected in that fashion, you can easily focus on a certain range of packets in the trace. Example:

Packet1

Packet2

Packet3

Packet4

Packet5

<<22 bytes ICMP echo request>>

Packet6

Packet7

Packet8

Packet9

Packet10

<<33 bytes ICMP echo request>>

Packet11

Packet12

...

We know that the issue was reproduced between 22 and 33 bytes ping markers, we can only focus on the activity taking place between packet #6 and packet # 10. Consider that it was a 50000 packets trace, you now isolated the problem down to 5 packets. (you may not be always lucky that much J)

You might be wondering "how can I identify those 22 and 33 bytes ICMP packets in the network trace". Here's a trick that I generally use. I first apply the following Wireshark filters in the network trace:

ip.len==50 and icmp (to identify the 22 bytes ping)

ip.len==61 and icmp (to identify the 33 bytes ping)

9) One of the most important points that you need to take into consideration is collecting simultaneous network traces where possible. With “simultaneous network traces” I mean “collecting a network trace on the source and on the target systems at the same time”. That may not be always possible especially if one one of those systems is not controlled by you (example you’re troubleshooting a connectivity problem to a web site that belongs to another company)

Other than that, I cannot stress more how important it’s to collect simultaneous network traces. When troubleshooting network connectivity issues, you cannot conclude whether or not the target server received the packet, or it sent a response back to the source or the source received the response without simultaneous network traces. Similarly, in network performance issues, you cannot conclude whether or not the response delay stems from the network path in between or from target/source systems. Let me try to explain what I mean with a couple of examples:

Example1:

We look at a client side network trace and see that the client sends 3 x TCP SYN segments to target without a response:

No. Time Delta Source Destination Protocol Info

...

141154 2011-03-31 16:52:29.488847 0.000000 192.168.4.71 10.1.1.1 TCP 37389 > 443 [SYN] Seq=0 Win=65535 Len=0

141158 2011-03-31 16:52:29.488847 0.000000 192.168.4.71 10.1.1.1 TCP 37389 > 443 [SYN] Seq=0 Win=65535 Len=0

144808 2011-03-31 16:52:29.801347 0.312500 192.168.4.71 10.1.1.1 TCP 37389 > 80 [SYN] Seq=0 Win=65535 Len=0

By looking at the client side trace, can you answer the following?

=> Did the target server really receive the above 3 TCP SYN segments?

=> Did the target server send a response back to the above TCP SYN segment?

=> Did the target server really send the response and we didn’t see it at the client side?

All the answers are NO. You cannot say if the target server really received those TCP SYNs or received and sent a response back or didn’t send any response at all. To be able to correctly answer those questions, you will have to see the story from target server’s perspective by looking at a network trace collected on that system.

Example2:

We look at a client side network trace and see that HTTP response is sent by the HTTP server after 4 seconds:

Time Delta Source Destination Protocol Info

16:57:37.537895 0.000000 192.168.4.71 10.17.200.49 TCP 45221 > 80 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 SACK_PERM=1

16:57:37.787895 0.250000 192.168.4.71 10.17.200.49 TCP 45221 > 80 [ACK] Seq=1 Ack=1 Win=65535 [TCP CHECKSUM INCORRECT]

16:57:37.787895 0.000000 10.17.200.49 192.168.4.71 TCP 80 > 45221 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1380

16:57:37.787895 0.000000 192.168.4.71 10.17.200.49 HTTP GET /images/downloads/cartoons/thumb_1.jpg HTTP/1.1

16:57:38.053520 0.265625 10.17.200.49 192.168.4.71 TCP 80 > 45221 [ACK] Seq=1 Ack=356 Win=6432 Len=0

16:57:42.084770 4.031250 10.17.200.49 192.168.4.71 HTTP HTTP/1.1 200 OK (JPEG JFIF image)

16:57:42.084770 0.000000 10.17.200.49 192.168.4.71 HTTP Continuation or non-HTTP traffic

16:57:42.084770 0.000000 192.168.4.71 10.17.200.49 TCP 45221 > 80 [ACK] Seq=356 Ack=2761 Win=65535 [TCP CHECKSUM

16:57:42.350395 0.265625 10.17.200.49 192.168.4.71 HTTP Continuation or non-HTTP traffic

....

By looking at the client side trace, can you answer the following?

=> Does the 4 second delay come from the target server or a network device running in between?

=> Did the target server wait for 4 seconds before responding or did it immediately send a response back but we see it after 4 seconds at the client side?

All the answers are NO. You cannot say if that 4 seconds delay really comes from the target web server or network device (web proxy for example) running in between. To be able to correctly answer those questions, you will have to see the story from target server’s perspective by looking at a network trace collected on that system.

Hope this helps

Thanks,

Murat

When do we need to collect network traces?

2012-06-22T10:49:00Z

Many Microsoft support engineers dealing with customer technical issues ask for network traces to further troubleshoot and isolate a given problem. In this post I wanted to give you an idea about when we generally ask for a network trace so that you might want to take a similar approach for similar problems.

May be we can start with the question “When do we need to collect and analyze a network trace?”

Even though the answers might vary, generally you will need to collect and analyze a network trace in the below situations:

• You need to troubleshoot network connectivity problems

• You need to troubleshoot network performance problems

• You need to troubleshoot network security problems

• You need to understand network behavior of protocols and applications for baselining or capacity planning purposes

Also you can see below some example problem types that we get from our customers where we ask for network traces:

Network connectivity problem examples:

• Web browser cannot connect to Web server

• Remote share cannot be browsed

• Event Viewer cannot connect to remote event log service

• I get ‘RPC server is unavailable’ when I initiate AD replication

• We get ‘server not found’ error when starting the XYZ application (a 3rd party app)

• Exchange server doesn’t receive e-mails from the internet

• Sharepoint portal cannot be reached from clients in a certain site

• Sharepoint server cannot retrieve data from SQL server

• SCCM server cannot communicate with the SCCM agent

• 3rd party client application cannot connect to 3rd party server application over a VPN tunnel

Network performance problem examples:

• File copy between two servers takes too long

• Download through HTTP from the internet takes is slow

• Backing up one of our file servers through the network takes too long

• We see delays in browsing our web site

• FTP file transfers are too slow between certain sites

• Windows Explorer is too slow in showing the remote share content

• SQL server query performance over the WAN connections is too slow

• Outbound e-mails queue up on Exchange Edge server

• Outlook client cannot connect to Exchange CAS servers trough a load balancer

Network security problem examples:

• We would like to understand why File server1 tries to establish a session to 10.1.1.1 through TCP port 7789

• In our firewall logs, we see that certain clients try to access a certain site. Why do those clients try to access that site?

• We would like to see which process generates a specific TCP session

• We would like to see the authentication protocol that the clients use to authenticate to Server X

• Kerberos/NTLM authentication problems

• Certain SSL authentication issues

• As soon as we connect the client machine to a switchport, the switchport is disabled due to excessive traffic coming from the client. We would like to know the reason behind that

Hope this helps

Thanks,

Murat

HTTPS access through TMG fails from a certain VLAN with a very unusual error: FWX_E_SEQ_ACK_MISMATCH

2012-06-15T11:45:00Z

In this blog post, I’ll be talking about an interesting problem that I dealt with recently. The problem was that clients running in a certain VLAN were not able to establish HTTPS connections through TMG server. Due to the nature of the network, the clients should be configured as SecureNet clients (my customer cannot configure them as web proxy clients or use TMG client software because these machines are guest machines)

I asked for the usual data from our customer to find out what was happening during the problem:

- Network trace & HTTPWatch logs from a test client

- TMG data packager from the TMG server

1. After receiving the data, I started from client side. What I see on the client side is the client starts failing right after the initial TCP 3-way handshake:

Note: Please note that, for privacy purposes all IP addresses have been replaced with random addresses.

=> Client network trace:

(ip.addr eq 10.110.233.50 and ip.addr eq 172.16.1.1) and (tcp.port eq 50183 and tcp.port eq 443)

453 14:44:32 01.05.2012 27.1395045 0.0000000 10.110.233.50 172.16.1.1 TCP TCP: [Bad CheckSum]Flags=......S., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515135, Ack=0, Win=8192 ( Negotiating scale factor 0x2 ) = 8192

456 14:44:32 01.05.2012 27.1565249 0.0170204 172.16.1.1 10.110.233.50 TCP TCP:Flags=...A..S., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=2, Seq=2180033885 - 2180033888, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

457 14:44:32 01.05.2012 27.1565443 0.0000194 10.110.233.50 172.16.1.1 TCP TCP: [Bad CheckSum]Flags=...A...., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515136, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

458 14:44:32 01.05.2012 27.1585176 0.0019733 10.110.233.50 172.16.1.1 TLS TLS:TLS Rec Layer-1 HandShake: Client Hello.

465 14:44:32 01.05.2012 27.4744962 0.3159786 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #458] [Bad CheckSum]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

476 14:44:33 01.05.2012 28.0828875 0.6083913 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #458] [Bad CheckSum]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

494 14:44:34 01.05.2012 29.2948179 1.2119304 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #458]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

512 14:44:35 01.05.2012 30.3815127 1.0866948 172.16.1.1 10.110.233.50 TLS TLS:Continued Data: 2 Bytes

513 14:44:35 01.05.2012 30.3815385 0.0000258 10.110.233.50 172.16.1.1 TCP TCP:Flags=...A...., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

516 14:44:35 01.05.2012 30.5019345 0.1203960 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #458]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

535 14:44:37 01.05.2012 31.7018989 1.1999644 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #458] [Bad CheckSum]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

568 14:44:38 01.05.2012 33.1872833 1.4853844 172.16.1.1 10.110.233.50 TLS TLS:Continued Data: 6 Bytes

- Client cannot connect to remote web site because SSL/TLS negotiation doesn’t succeed because no response from the Web server is received (from client’s perspective)

2. Then I decided to check things from TMG server perspective. I first checked the network trace that was collected on the internal interface of TMG server through which the client request was received:

6457 14:33:49 01.05.2012 39.8915584 0.0000000 10.110.233.50 172.16.1.1 TCP TCP:Flags=......S., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515135, Ack=0, Win=8192 ( Negotiating scale factor 0x2 ) = 8192

6461 14:33:49 01.05.2012 39.9079944 0.0164360 172.16.1.1 10.110.233.50 TCP TCP:Flags=...A..S., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=0, Seq=2180033885, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

6462 14:33:49 01.05.2012 39.9084181 0.0004237 10.110.233.50 172.16.1.1 TCP TCP:Flags=...A...., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515136, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

6463 14:33:49 01.05.2012 39.9103936 0.0019755 10.110.233.50 172.16.1.1 TLS TLS:TLS Rec Layer-1 HandShake: Client Hello.

6489 14:33:49 01.05.2012 40.2259991 0.3156055 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #6463]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

6614 14:33:50 01.05.2012 40.8343158 0.6083167 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #6463]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

6806 14:33:51 01.05.2012 42.0457229 1.2114071 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #6463]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

6872 14:33:52 01.05.2012 43.1311020 1.0853791 172.16.1.1 10.110.233.50 TCP TCP:Flags=...A..S., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=0, Seq=2180033885, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

6873 14:33:52 01.05.2012 43.1314010 0.0002990 10.110.233.50 172.16.1.1 TCP TCP:Flags=...A...., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

6891 14:33:52 01.05.2012 43.2517820 0.1203810 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #6463]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

7110 14:33:54 01.05.2012 44.4514449 1.1996629 10.110.233.50 172.16.1.1 TCP TCP:[ReTransmit #6463]Flags=...AP..., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=127, Seq=367515136 - 367515263, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

7481 14:33:55 01.05.2012 45.9360680 1.4846231 172.16.1.1 10.110.233.50 TCP TCP:Flags=...A.R.., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=0, Seq=2180033886, Ack=367515136, Win=8192 (scale factor 0x0) = 8192

- TMG server doesn’t really send responses back to the client

3. Then I decided to check the network trace collected on the external interface of the TMG server:

21 14:33:49 01.05.2012 39.6940232 0.0000000 10.110.235.202 172.16.1.1 TCP TCP:Flags=......S., SrcPort=55073, DstPort=HTTPS(443), PayloadLen=0, Seq=367515135, Ack=0, Win=8192 ( Negotiating scale factor 0x2 ) = 8192

22 14:33:49 01.05.2012 39.7097097 0.0156865 172.16.1.1 10.110.235.202 TCP TCP:Flags=...A..S., SrcPort=HTTPS(443), DstPort=55073, PayloadLen=0, Seq=2180033885, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

23 14:33:52 01.05.2012 42.9329903 3.2232806 172.16.1.1 10.110.235.202 TCP TCP:Flags=...A..S., SrcPort=HTTPS(443), DstPort=55073, PayloadLen=0, Seq=2180033885, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

24 14:33:55 01.05.2012 45.7379523 2.8049620 172.16.1.1 10.110.235.202 TCP TCP:Flags=...A.R.., SrcPort=HTTPS(443), DstPort=55073, PayloadLen=0, Seq=2180033886, Ack=367515136, Win=8192 (scale factor 0x0) = 8192

- External Web server sends a response to initial TCP 3-way handshake request that is forwarded by TMG, but TMG server doesn’t proceed with the connection

4. Then I checked the Web Proxy/Firewall log on the TMG server:

01.05.2012 14:33 Denied 10.110.233.50 50183 172.16.1.1 443 0xc0040034 FWX_E_SEQ_ACK_MISMATCH

01.05.2012 14:33 Denied 10.110.233.50 50183 172.16.1.1 443 0xc0040034 FWX_E_SEQ_ACK_MISMATCH

01.05.2012 14:33 Denied 10.110.233.50 50183 172.16.1.1 443 0xc0040034 FWX_E_SEQ_ACK_MISMATCH

When I check more details on that error code, I see that we fail because we receive a TCP packet with an invalid sequence number:

http://msdn.microsoft.com/en-us/library/ms812624.aspx/

FWX_E_SEQ_ACK_MISMATCH 0xC0040034 A TCP packet was rejected because it has an invalid sequence number or an invalid acknowledgement number.

So TMG Server drops the TCP ACK packet (3^rd TCP packet in TCP 3-way handshake) coming from the client because it has an invalid TCP ACK number

5. The problem was also visible in the ETL trace:

…

… handshake packet is dropped becuase ACK (2180033888) no equal ISN(peer)+1 (2180033886)

… Warning:The packet failed TCP sequence validation

… Warning:The packet is dropped because of SEQ_ACK_MISMATCH

…

6. When we check the TMG side network trace we see it there:

SequenceNumber: 367515135 (0x15E7D5FF)

SequenceNumber: 2180033885 (0x81F0AD5D)

AcknowledgementNumber: 367515136 (0x15E7D600)

SequenceNumber: 367515136 (0x15E7D600)

AcknowledgementNumber: 2180033888 (0x81F0AD60)

That Acknowledgement number SHOULD HAVE BEEN 2180033886 (0x81F0AD5E)

So TMG ignores the rest of the session (like TLS client hello coming from the client machine)

6463 14:33:49 01.05.2012 39.9103936 0.0019755 10.110.233.50 172.16.1.1 TLS TLS:TLS Rec Layer-1 HandShake: Client Hello.

7. When I check the client side trace, I see that the ACK number in the TCP ACK packet is really set to the wrong value (2180033888) by the client:

Frame: Number = 6462, Captured Frame Length = 60, MediaType = ETHERNET

+ Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-11-22-33-44-55],SourceAddress:[00-12-34-56-78-1B]

+ Ipv4: Src = 10.110.233.50, Dest = 172.16.1.1, Next Protocol = TCP, Packet ID = 24041, Total IP Length = 40

- Tcp: Flags=...A...., SrcPort=50183, DstPort=HTTPS(443), PayloadLen=0, Seq=367515136, Ack=2180033888, Win=64860 (scale factor 0x0) = 64860

SrcPort: 50183

DstPort: HTTPS(443)

SequenceNumber: 367515136 (0x15E7D600)

AcknowledgementNumber: 2180033888 (0x81F0AD60)

+ DataOffset: 80 (0x50)

+ Flags: ...A....

Window: 64860 (scale factor 0x0) = 64860

Checksum: 0x4B5D, Good

UrgentPointer: 0 (0x0)

8. One can think that it’s a problem with TCPIP stack on the client, but when we check the TCP SYN ACK packet (the second TCP packet sent by TMG server before the TCP ACK with wrong sequence number is sent by the client) we see that the client receives that TCP SYN ACK packet with 2 bytes extra data (which is something unusual for a TCP SYN ACK packet - such packets shouldn’t have data just should have TCP header):

Frame: Number = 456, Captured Frame Length = 60, MediaType = ETHERNET

+ Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-11-22-33-44-55],SourceAddress:[00-12-34-56-78-1B]

+ DestinationAddress: Microsoft Corporation [00-11-22-33-44-55]

+ SourceAddress: Test Data [00-12-34-56-78-1B]

EthernetType: Internet IP (IPv4), 2048(0x800)

- Ipv4: Src = 172.16.1.1, Dest = 10.110.233.50, Next Protocol = TCP, Packet ID = 1342, Total IP Length = 46

+ Versions: IPv4, Internet Protocol; Header Length = 20

+ DifferentiatedServicesField: DSCP: 0, ECN: 0

TotalLength: 46 (0x2E)

Identification: 1342 (0x53E)

+ FragmentFlags: 0 (0x0)

TimeToLive: 120 (0x78)

NextProtocol: TCP, 6(0x6)

Checksum: 46957 (0xB76D)

SourceAddress: 194.53.208.72

DestinationAddress: 10.110.233.50

- Tcp: Flags=...A..S., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=2, Seq=2180033885 - 2180033888, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

SrcPort: HTTPS(443)

DstPort: 50183

SequenceNumber: 2180033885 (0x81F0AD5D)

AcknowledgementNumber: 367515136 (0x15E7D600)

+ DataOffset: 96 (0x60)

+ Flags: ...A..S.

Window: 64240 ( Scale factor not supported ) = 64240

Checksum: 0x365C, Good

UrgentPointer: 0 (0x0)

- TCPOptions:

- MaxSegmentSize: 1

type: Maximum Segment Size. 2(0x2)

OptionLength: 4 (0x4)

MaxSegmentSize: 1380 (0x564)

- TCPPayload: SourcePort = 443, DestinationPort = 50183

UnknownData: Binary Large Object (2 Bytes)

That’s why the TCPIP stack running on the client sends a TCP ACK number which is 2 more than the value that should be:

ACK number sent by the client: AcknowledgementNumber: 2180033888 (0x81F0AD60)

The correct ACK number that should have been sent: AcknowledgementNumber: 2180033886 (0x81F0AD5E)

9. And when we check the TCP SYN ACK packet that is leaving the TMG server, we don’t see such an extra 2 bytes:

Frame: Number = 6461, Captured Frame Length = 60, MediaType = ETHERNET

+ Ethernet: Etype = Internet IP (IPv4),DestinationAddress:[00-11-22-33-44-55],SourceAddress:[00-12-34-56-78-1B]

+ Ipv4: Src = 172.16.1.1, Dest = 10.110.233.50, Next Protocol = TCP, Packet ID = 1342, Total IP Length = 44

- Tcp: Flags=...A..S., SrcPort=HTTPS(443), DstPort=50183, PayloadLen=0, Seq=2180033885, Ack=367515136, Win=64240 ( Scale factor not supported ) = 64240

SrcPort: HTTPS(443)

DstPort: 50183

SequenceNumber: 2180033885 (0x81F0AD5D)

AcknowledgementNumber: 367515136 (0x15E7D600)

+ DataOffset: 96 (0x60)

+ Flags: ...A..S.

Window: 64240 ( Scale factor not supported ) = 64240

Checksum: 0x365E, Good

UrgentPointer: 0 (0x0)

- TCPOptions:

- MaxSegmentSize: 1

type: Maximum Segment Size. 2(0x2)

OptionLength: 4 (0x4)

MaxSegmentSize: 1380 (0x564)

So that 2 bytes extra data is somehow added to TCP SYN ACK by something else (like the NIC driver on the TMG server, a network device running in between (like Wireless access point etc) or the NIC driver on the client machine

SUMMARY:

==========

In summary the HTTPS connectivity problem stems from an issue between the Client and TMG server (including the NIC layer or below on the client and server and the network devices/links in between the two)

My customer informed me that the issue was visible with any clients which makes it unlikely that it’s a client side issue. I advised my customer to update NIC drivers on the TMG server side and check the network devices running in the path and upgrade firmwares where possible.

Hope this helps

Thanks,

Murat

Outlook anywhere (RPC over HTTPS) access to Exchange 2010 server via TMG 2010 fails after some time

2012-06-12T14:22:00Z

In this blog post, I’ll be discussing an Exchange 2010 publishing on TMG 2010 issue. The problem was that after sometime Outlook clients were failing to access to Exchange 2010 server via RPC over HTTPS.

There may be many different reasons for Exchange publishing problems, but in this case everything seemed green in the “Test Rule” output that we ran on TMG server. So from TMG server perspective everything seemed good. The output I mention is similar to below one:

Note: This is taken from excellent tutorial written by Richard Hicks

http://www.isaserver.org/tutorials/Publishing-Exchange-Outlook-Web-App-OWA-Microsoft-Forefront-Threat-Management-Gateway-TMG-2010-Part2.html

So we decided to collect TMG data packager to better understand what was going on while the problem occurred. In the TMG data packager output we realized that some of the incoming TCP connections were being dropped by TMG server with the error QUOTA EXCEEDED.

Indeed, we saw that TMG server didn’t respond to some TCP SYNs and the reason was that the flood mitigation mechanism was triggered:

Normally a remote Outlook client will establish more than one TCP connection but it shouldn’t trigger flood mitigation under normal circumstances. Something in the above screen shot might have drawn your attention:

All incoming TCP connections come from the same source IP address: 192.168.200.1

Actually that was the key point in understanding the root cause of the problem. As per customer’s network setup, the router running in front of the TMG server (by the way, TMG server was running on a single NIC in the DMZ network) was NATting source IP address of all external systems and that was why we saw that all incoming connections were coming from the same IP address. After turning flood mitigation off on TMG server, the issue was resolved (The customer increased the limits later on but in general it looks like it doesn’t make much sense using flood mitigation since all legitimate traffic is received from the same IP address which is 192.168.200.1). I also would like to thank to Franck who helped me a lot while dealing with this issue.

Hope this helps

Thanks,

Murat

Getting HTTP 500 Internal server error when accessing a published web site through ISA 2004

2012-05-23T10:47:00Z

In this post, I’ll be talking about a web publishing problem and how I dealt with it. The problem was that external clients were failing to access an internal Web server published on ISA 2004 server with HTTP 500 internal error.

As usual, I asked the following logs from our customer when reproducing the problem:

- Collecting an ISA data packager while reproducing the problem (as part of ISA Best practices Analyzer log). The tool could be downloaded from the below link:

http://www.microsoft.com/en-us/download/details.aspx?id=811

- Collecting a network trace from the internal web server

- Collecting a network trace and Fiddler trace from an external test client. It could be downloaded at the following link:

http://www.fiddler2.com/fiddler2/

Note: Fiddler or similar tools (like HTTPWatch – we also use it) provide useful information even if the connection is clear text HTTP. For HTTPS connections it’s nearly a requirement to collect it to see what’s going on from client’s perspective. Another possibility is collecting WinInet/WinHTTP ETL traces which I plan to discuss in another post.

Troubleshooting:

After collecting the logs, I started troubleshooting the problem

a) I first checked the Web proxy logs (collected as part of Data packager logs) and saw the same problem there: (I included only a part of the log and also changed the names deliberately)

Result code is -2146893022 which is FFFFFFFF80090322 which is SEC_E_WRONG_PRINCIPAL

Actually the web listener used by the given web publishing rule doesn’t have authentication configured. But that error might also be seen when certificate related issues are seen.

b) Then I decided to check the ETL trace that was also collected as part of ISA data packager. Please note that the ETL trace collected as part of data packager could only be converted to human readable format by Microsoft support but we also provide a lightweight version of the same facility as part of the product. You can do that as follows:

(Before reproducing the problem you have to enable logging from “Enable Diagnostic Logging” and once the problem is reproduced you have to disable logging by selecting “Disable Diagnostic Logging”)

When checking ETL traces, one of the key parameters is the filter info which is also a part of Web proxy log. Example:

So I focused on the relevant filter info and have seen the following problem there: (please note that the ETL output is much more detailed than shown below)

…

… Failed - server name doesn't match. local name : web.contoso.com, cert name: *.contoso.com

…

After seeing the error above, I realized that we were hitting the known limitation with ISA 2004 and wildcard certificates used on published servers:

http://technet.microsoft.com/en-us/library/cc302619.aspx Troubleshooting SSL Certificates in ISA Server 2004 Publishing

I am using wildcard certificates and getting the error: 500 Internet Server Error – The target principal name is incorrect.

ISA Server 2004 only supports wildcard certificates on the ISA Server computer. ISA Server 2006 also supports use of wildcard certificates on the published Web server. When using HTTPS to HTTPS bridging, you cannot use wildcard certificates to authenticate the back-end Web server. Instead, on the internal Web server, create a new certificate that matches the name of the internal Web server, as specified on the To tab in the Web publishing rule. For more information about configuring this scenario, see Publishing Multiple Web Sites using a Wildcard Certificate in ISA Server 2004 (www.microsoft.com).

For confirmation purposes, I also checked the network trace collected from the internal Web server and saw that the web server was really sending a wildcard certificate to ISA 2004 server:

=> The relevant frame:

Frame: Number = 8649, Captured Frame Length = 2974, MediaType = ETHERNET

…

- TLS: TLS Rec Layer-1 HandShake: Server Hello. Certificate.

- TlsRecordLayer: TLS Rec Layer-1 HandShake:

ContentType: HandShake:

+ Version: TLS 1.0

Length: 4786 (0x12B2)

- SSLHandshake: SSL HandShake Certificate(0x0B)

HandShakeType: ServerHello(0x02)

Length: 77 (0x4D)

+ ServerHello: 0x1

HandShakeType: Certificate(0x0B)

Length: 4697 (0x1259)

- Cert: 0x1

CertLength: 4694 (0x1256)

- Certificates:

CertificateLength: 1457 (0x5B1)

+ X509Cert: Issuer: ContosoSubCA,contoso,com, Subject: *.contoso.com

…

- The web server has a wildcard certificate assigned (*.contoso.com)

The resolution to this problem is to assign a new certificate to the internal Web server which is not a wildcard certificate. You can find more information below:

http://technet.microsoft.com/library/cc302625.aspx Publishing Multiple Web Sites Using a Wildcard Certificate in ISA Server 2004)

Hope this helps

Thanks,

Murat

Outlook MAPI connection to Exchange 2010 CAS fails through UAG 2010 direct access tunnel

2012-05-22T11:39:00Z

In a recent case, I dealt with an Outlook MAPI connection failure problem through direct access tunnel (configured with UAG 2010) and I’ll be talking about how I troubleshooted this issue in this post.

The problem was reported as Outlook 2010 clients were failing to access Exchange 2010 servers that run behind a UAG 2010 server. We decided to collect the following logs to better understand the root cause of the problem:

=> On the direct access client:

netsh wfp capture start

netsh trace start scenario=directaccess capture=yes tracefile=darepro.etl maxsize=350

nmcap /network * /capture /file DAClient.chn:100M

=> On the UAG 2010 server:

nmcap /network * /capture /file DAServer.chn:100M

Note 1: You have to install Network Monitor 3.4 to run the nmcap command

http://www.microsoft.com/downloads/details.aspx?displaylang=en&FamilyID=983b941d-06cb-4658-b7f6-3088333d062f

Note 2: “netsh wfp capture start” command collects WFP (windows filtering platform) and Ikeext (ipsec negotiation) etl traces

Note 3: “netsh trace start scenario=directaccess” command collects direct access related component ETL traces (like ip helper service, tcpip, afd, dns, winhttp, wininet etc). You can see the ETL traces for which components are collected for the “directaccess” scenario by running “netsh trace show scenario directaccess)

Note 4: Please note that all such commands need to be run from an elevated command prompt. And all the commands (except nmcap) are supported on Windows 7/2008 R2 onwards.

After starting the logs as given above, we reproduced the problem and stopped collecting logs as below:

- CTRL + C stops nmcap

- netsh wfp capture stop (for WFP tracing)

- netsh trace stop (for Directaccess related tracing)

Troubleshooting:

From the ETL trace (collected as a result of netsh trace start scenario=directaccess), I was able to see that the Outlook client was failing to resolve MAPI interface endpoint information (IP:port) from the remote Exchange 2010 server which is done via RPC endpoint mapper:

31508 15:37:26.9645379 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV6 PID=5788 (0x169C)) created.

31509 15:37:26.9645392 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x00000000042E4CF0 (Family=IPV6, PID=5788 (0x169C)) created with status = Success.

31512 15:37:26.9647035 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000042E4CF0 acquired port number 61581 (0xF08D).

31513 15:37:26.9647172 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0:0:0:0:0:0:0:0:61581 (0xF08D)) bound.

31517 15:37:26.9647660 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from ClosedState to SynSentState, SndNxt = 0 (0x0).

31518 15:37:26.9648157 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 attempted to acquire weak reference on port number 61581 (0xF08D) inherited from endpoint 0x00000000042E4CF0. Successful = TRUE.

31519 15:37:26.9648191 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x00000000042E0AE0 (local=2001:0:0A0B:86E8:388E:FCB:4337:1876:61581 (0xF08D) remote=2002:0A01:86E8:8001:0:0:A0B:0202:135 (0x87)) requested to connect.

=> A0B:0202:135 is the internal IP address (10.11.2.2) of Exchange 2010 CAS server and the target port (135)

31520 15:37:26.9648319 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Inspect Connect has been completed on Tcb 0x00000000042E0AE0 with status = Success.

31521 15:37:26.9648452 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x00000000042E0AE0 is going to output SYN with ISN = 2258039006 (0x8696F0DE), RcvWnd = 8192 (0x2000), RcvWndScale = 8 (0x8).

31522 15:37:26.9648469 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 (local=2001:0:C32A:86E8:388E:FCB:4337:1876:61581 (0xF08D) remote=2002:C32A:86E8:8001:0:0:A0B:9522:135 (0x87)) connect proceeding.

31523 15:37:26.9648542 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 1 (0x1) and Sequence number = 2258039006 (0x8696F0DE).

31541 15:37:27.0024371 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from SynSentState to EstablishedState, SndNxt = 2258039007 (0x8696F0DF).

31542 15:37:27.0024392 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 1 (0x1). ThSeq = 3786409003 (0xE1B0042B).

31543 15:37:27.0024439 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 (local=2001:0:0A0A:2222:1111:FCB:4337:1876:61581 (0xF08D) remote=2002:0A0A:86E8:8001:0:0:A0B:9522:135 (0x87)) connect completed. PID = 5788 (0x169C).

=> TCP 3-way handshake has been finished here.

31547 15:37:27.0027145 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0, delivery 0x00000000042E0C40, Request 0x000000000408C6B0 posted for 0x0000000000000400 bytes, flags = 0 (0x0). RcvNxt = 3786409003 (0xE1B0042B).

31550 15:37:27.0027367 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 send posted posted 72 (0x48) bytes at 2258039007 (0x8696F0DF).

=> We send the RPC map request to the Exchange 2010 server here. (frame #31550)

31552 15:37:27.0027949 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 72 (0x48) and Sequence number = 2258039007 (0x8696F0DF).

31556 15:37:27.0427894 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Cumulative ACK updated cwnd = 2300 (0x8FC).

31557 15:37:27.0428317 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 delivery 0x00000000042E0C40 satisfied 0x0000000000000018 bytes 0x0000000000000400 requested. IsFullySatisfied = 0 (0x0). RcvNxt = 3786409003 (0xE1B0042B).

31559 15:37:27.0428553 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 24 (0x18). ThSeq = 3786409003 (0xE1B0042B).

=> We get RPC map response from Exchange 2010 server here (frame #31559), it's just 24 bytes. Normally it should have been some 150 bytes or so.

31563 15:37:27.0430051 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from EstablishedState to FinWait1State, SndNxt = 2258039079 (0x8696F127).

31564 15:37:27.0430171 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 1 (0x1) and Sequence number = 2258039079 (0x8696F127).

31565 15:37:27.0432076 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0:0:0:0:0:0:0:0:61581 (0xF08D)) closed.

31566 15:37:27.0432123 OUTLOOK.EXE (5788) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000042E4CF0 released port number 61581 (0xF08D). WeakReference = FALSE.

31590 15:37:27.0458327 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 1 (0x1). ThSeq = 3786409027 (0xE1B00443).

31591 15:37:27.0458588 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from FinWait1State to ClosingState, SndNxt = 2258039080 (0x8696F128).

31592 15:37:27.0458605 System (4) TCPIP_MicrosoftWindowsTCPIP TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 delivery 0x00000000042E0C40 delivering FIN. RcvNxt = 3786409028 (0xE1B00444).

=> TCP session has been gracefully terminated here.

(Note: The ETL trace could be opened with Network Monitor 3.4)

- In the above trace, Outlook client establishes a TCP connection TCP port 135 at Exchange 2010 server.

- But the session is terminated gracefully quickly after it’s established. Most likely we didn't receive the response we expected (where the endpoint information would be seen). Since this is through direct access tunnel, we cannot see the packet in clear, we're making comments based on TCPIP driver ETL trace.

Then I decided to check UAG server to Exchange server activity from the UAG server side network trace. In that network trace, I saw that Exchange server was successfully responding to map requests sent through RPC endpoint mapper connection to Exchange server:

Note: Please note that all IP addresses are deliberately changed.

=> Endpoint mapper request sent from UAG server to Exchange 2010 server:

Internet Protocol Version 4, Src: 10.1.1.1 (10.1.1.1), Dst: 10.11.2.2(10.11.2.2)

Transmission Control Protocol, Src Port: 33654 (33654), Dst Port: 135 (135), Seq: 2005198912, Ack: 3769475906, Len: 156

Distributed Computing Environment / Remote Procedure Call (DCE/RPC) Request, Fragment: Single, FragLen: 156, Call: 2 Ctx: 0, [Resp: #32049]

DCE/RPC Endpoint Mapper, Map

Operation: Map (3)

[Response in frame: 32049]

UUID pointer:

Referent ID: 0x00000001

UUID: 00000000-0000-0000-0000-000000000000

Tower pointer:

Referent ID: 0x00000002

Length: 75

Number of floors: 5

Floor 1 UUID: MAPI

Floor 2 UUID: Version 1.1 network data representation protocol

Floor 3 RPC connection-oriented protocol

Floor 4 TCP Port:135

Floor 5 IP:0.0.0.0

Handle: 0000000000000000000000000000000000000000

Max Towers: 15

=> Endpoint mapper response sent from Exchange 2010 server to UAG server:

Internet Protocol Version 4, Src: 10.11.2.2(10.11.2.2), Dst: 10.1.1.1 (10.1.1.1)

Transmission Control Protocol, Src Port: 135 (135), Dst Port: 33654 (33654), Seq: 3769475906, Ack: 2005199068, Len: 152

Distributed Computing Environment / Remote Procedure Call (DCE/RPC) Response, Fragment: Single, FragLen: 152, Call: 2 Ctx: 0, [Req: #32046]

DCE/RPC Endpoint Mapper, Map

Operation: Map (3)

[Request in frame: 32046]

Handle: 0000000000000000000000000000000000000000

Num Towers: 1

Tower array:

Max Count: 15

Offset: 0

Actual Count: 1

Tower pointer:

Referent ID: 0x00000003

Length: 75

Number of floors: 5

Floor 1 UUID: MAPI

Floor 2 UUID: Version 1.1 network data representation protocol

Floor 3 RPC connection-oriented protocol

Floor 4 TCP Port:41376

Floor 5 IP:10.11.2.7

Return code: 0x00000000

I realized something weird in the map response coming back from RPC endpoint mapper on Exchange 2010 server:

Floor 5 IP:10.11.2.7

Actually I would expect to see 10.11.2.2 as the endpoint IP address in the RPC map response header (the IP header still has the source IP address 10.11.2.2) but it wasn’t. It was set to 10.11.2.7. Actually that happens when Exchange (or other servers that expose RPC interfaces) run behind a HW load balancer. So in this scenario:

10.11.2.2 is the VIP (virtual IP) or load balanced IP address of the Exchange 2010 CAS array. 10.11.2.7 is the dedicated IP address of the Exchange 2010 server that is responding to UAG server’s RPC map request (sent to discover the MAPI RPC endpoint information)

HW load balancer modifies the IP headers (in map request or in map response) but it doesn’t touch the RPC header buried inside the IP packet.

OK, so far so good. Even though we get endpoint information with a different IP address than we expected, we still get an RPC map response succesfully. So why is that processing still failing?

Well, this was the key point J . Please remember that UAG server uses TMG server to protect itself and RPC filter as part of TMG server by default doesn’t allow such RPC responses due to security reasons. (the endpoint IP address is different than the one RPC map request sent to)

The resolution here was to apply the script mentioned in the below article on the TMG server (which is the same box with UAG 2010 server):

FIX: The TMG remote management console does not display the status of the TMG 2010 server if certain Group Policy preferences settings are set

http://support.microsoft.com/kb/982604

Actually the article itself is unrelated here but by running this script, we instruct the RPC filter not to drop RPC responses when RPC endpoint IP address given in the RPC header is different than the IP address to which the RPC request was sent.

You might be wondering how the RPC map request was sent to Exchange 2010 with IPv4 address whereas the original request was sent with IPv6 by the direct access client. Well the answer is DNS64/NAT64 functionality present in UAG 2010 server (and now present in Windows Server 2012 consumer preview). You can find more details about how DNS64/NAT64 works at the following article:

http://blogs.technet.com/b/edgeaccessblog/archive/2009/09/08/deep-dive-into-directaccess-nat64-and-dns64-in-action.aspx

Hope this helps

Thanks,

Murat

PDF file corrupted when downloaded through TMG server

2012-05-21T16:44:00Z

Recently I dealt with a problem where PDF file downloaded from a certain external web site was always corrupted and I would like to talk about how I troubleshooted that problem. The client was connected to internet through a four node TMG 2010/SP2 array.

We decided to collect the following logs to better understand why the file was corrupted:

- Network trace on the internal client

- TMG data packager on one of the TMG servers

(Since the problem was reproducible by setting any of the TMG servers as the proxy server, we set one of the array members as a proxy server to collect less logs)

Note: TMG data packager is installed as part of TMG Best practices Analyzer installation

http://www.microsoft.com/en-us/download/details.aspx?id=17730

Microsoft Forefront Threat Management Gateway Best Practices Analyzer Tool

The results from the log analysis were as below:

- There weren’t any connectivity problems present in the TCP sessions (through which the file was downloaded) in the network trace collected on the client, internal and external interfaces of TMG server

- The error code for the given file download was 13: (taken from Web proxy log)

Action	Client IP	Destination Host IP	Server Name	Operation	Result Code	URL
Failed	10.200.1.20	10.1.1.1	Proxy1	GET	13	http://.../Report.pdf
Failed	10.200.1.20	10.1.1.1	Proxy1	GET	13	http://.../Report.pdf

Note: IP addresses/links/proxy names etc are deliberately changed

Error 13 is “The data is invalid”:

C:\>net helpmsg 13

The data is invalid.

So TMG server thinks that the received data was invalid. That also explains why the downloaded file was corrupted.

Then I decided to take a look at the ETL trace which was also collected with TMG Data packager. Actually the root cause behind why TMG server thought the data was invalid was clearly visible there:

…

... GZIP Dempression failed. Drop the request. (connection closed=0) 0x8007000d(ERROR_INVALID_DATA)

…

Because the file decompression fails on TMG server, TMG server finalizes the session with Error_Invalid_data (error 13)

Note: Please note that you have to contact Microsoft support for ETL trace conversion

Note: You can also collect a similar diagnostics log from TMG server’s console:

For troubleshooting purposes, I suggested to turn off Compression on TMG server:

(We remove “External” from the “Request compressed HTTP content when sending requests to these network elements” section.)

As expectedly the corrupted file download problem was resolved. When we make the above configuration change actually we ask the TMG server not to ask for compression when sending HTTP requests out to external web servers. So the file was downloaded in uncompressed format. Please note that TMG server asks for compression for HTTP requests sent to external web sites by default and that provides some bandwidth saving by minimizing the amount of data transferred.

We decided that the problem was somehow related to the target web site or upstream Web proxy because the same TMG server was able to successfully download HTTP content in compressed format from other external web sites.

Normally it’s possible to turn off compression for a specific web site (which could be configured from “Exceptions” tab in the above screen shot). But the TMG array in question was configured to use an upstream proxy for all external web traffic. So creating an exception wouldn’t make much difference here. Our customer decided to keep HTTP compression off (and re-enable it once the file downloads from the given web site were finished)

Hope this helps

Thanks,

Murat

Internet Explorer doesn't display ISA or TMG error message 502 when connecting to HTTPS servers

2011-09-22T16:28:00Z

Hi there,

I would like to talk about an issue that I have dealt with recently regarding Internet Explorer and displaying TMG error messages.

The problem reported was that newer IE versions (like 8 or 9) didn’t display the regular TMG error message which is displayed when the access rule allows certain users and the current user is not one of the allowed users (Error Code: 502 Proxy Error. The Forefront TMG denied the specified Uniform Resource Locator (URL). (12202)),instead the "Page not found" error was displayed and that was causing some help desk calls since the user thought that the target web site was not reachable based on the displayed error message whereas the real problem was user was not allowed to access the given web site.

IE6 didn’t have the same problem. Then we started investigating the problem from TMG perspective to make sure that it wasn’t something stemming from TMG server side. After some further troubleshooting (network traces), we found out that TMG was sending the regular error page back to the client but somehow it wasn’t displayed by the IE client.

Then we focused on the IE side. After some further investigation, I found out that it was the expected default behavior for newer Internet Explorer versions (8 and 9, we haven’t tested 7 but this might apply to 7 as well) for security reasons. You can find below more information about the vulnerability that could be exploited when IE uses Proxy servers to connect to target servers:

Pretty-Bad-Proxy: An Overlooked Adversary in Browsers’ HTTPS Deployments

Having said that, there’s a registry key which allows you to turn this enhanced security feature off in newer IE versions. You can see the details below on how to do this on the client machines:

http://msdn.microsoft.com/en-us/library/ms537184(VS.85).aspx Introduction to Feature Controls

- You’ll need to create the highlighted key at the given path on a client machine:

HKEY_LOCAL_MACHINE (or HKEY_CURRENT_USER)
     SOFTWARE
          Microsoft
               Internet Explorer
                    Main
                         FeatureControl
                                      FEATURE_SHOW_FAILED_CONNECT_CONTENT_KB942615     (Note: you’ll also need to create that registry key under “FeatureControl”)

Reg key name: Iexplore.exe

Type: REG_DWORD

Value: 0x00000001

You can also get some more information at http://msdn.microsoft.com/en-us/library/dd565641(VS.85).aspx#eventLog Event 1065 - Web Proxy Error Handling Changes

I would like to re-emphasize that it normally shouldn’t be turned off from security perspective, so please implement it at your own risk.

Hope this helps

Thanks,

Murat

TMG initiates active FTP connections to external servers even though it's configured for passive FTP - a problem with FTP over HTTP

2011-09-21T09:15:00Z

Hi there,

In this blog post, I’ll be talking about another TMG problem where FTP over HTTP was failing through TMG server.

Let me first summarize the scenario:

- Internet Explorer clients need to connect to an external FTP site through TMG server

- Due to some other requirements, this FTP site needs to be accessed passively

FTP filter in TMG server already uses passive FTP when connecting to external FTP sites:

(Note: And this is the default behavior, please see http://blogs.technet.com/b/yuridiogenes/archive/2010/03/16/error-502-active-ftp-not-allowed-when-trying-to-list-files-in-a-ftp-session-behind-forefront-tmg-2010.aspx for more information.

That was also the case in my customer’s scenario but passive FTP connection to the target FTP server was still failing. After some troubleshooting, we found out that TMG server was trying to connect to the target FTP site actively even FTP filter was configured as above.

Normally, when you type ftp://target-FTP-Server-FQDN in the IE address bar and IE is configured to use a Proxy server, the connection request will be sent as an HTTP request to the Proxy server (and the FTP GET request will be inside that HTTP request), this is also called FTP over HTTP. So the request flow will be similar to below:

a) Client sends the request via FTP over HTTP to the Proxy server

b) Proxy server connects to the target FTP server via FTP procotol

After some further troubleshooting with TMG data packager and the network trace analysis, I found out that FTP filter wasn’t involved in when Proxy server receives FTP over HTTP traffic from clients and hence FTP filter setting doesn’t apply to FTP over HTTP requests.

The resolution was to set the NonPassiveFTPTransfer registry key on the TMG server and restart the firewall service:

Note: You can find more information about that registry key at http://support.microsoft.com/kb/300641 How to enable passive CERN FTP connections through ISA Server 2000, 2004, or 2006

As mentioned above, after the registry key is created, you’ll need to stop and then start firewall service from an elevated command prompt:

net stop fwsrv

net start fwsrv

To summarize; even though “NonPassiveFTPTransfer” registry key shouldn’t be needed for TMG server, the exact requirements are as follows:

a) If the internal client sends the FTP request directly through FTP procotol, there’s no need to change anything on TMG server side as the FTP filter will kick in and the FTP connection to the external FTP server will be initiated passively (Examples: Command prompt FTP client, 3rd party FTP client applications, IE which isn’t configured to use a Proxy server etc)

b) If the internal client sends the FTP request through FTP over HTTP procotol, then the changes mentioned above needs to be implemented on TMG server side in order for TMG server to initiate the outbound FTP connection passively (Example: IE which is configured to use a Proxy server)

Hope this helps

Thanks,

Murat

Java applications and TMG access rules that require authentication

2011-09-21T08:10:00Z

Hi there,

In this blog post, I’ll be talking about a TMG related issue. Actually it’s not an issue that stems from TMG itself but the way TMG server is configured (using authenticated rules on TMG server) triggers the problem.

This is already a known fact and we have a KB article that explains this issue (JVM applications cannot send authentication information when requested) and the workaround is to turn off authentication for the access rule that will allow the client’s connection to external networks:

http://support.microsoft.com/kb/925881/ An ISA server or Forefront Threat Management Gateway server requests credentials when client computers in the same domain use Internet Explorer to access Web sites that contain Java programs

So if you see all or some parts of a web page is not displayed correctly and you see Proxy authentication required or similar messages on the client side and you suspect that Java is involved somehow you’ll have to implement the steps mentioned at the above article.

But sometimes it may not be that clear which was the case in my scenario. The customer reported that videos at an on demand video conference site weren’t successfully viewed and the application running inside IE was displaying an unrelated error. I suspected that we were hitting the problem mentioned above and then requested the customer to configure a temp access rule to allow all outbound access for “All users”, then the videos started to play J

Then we changed the rule target to the target web site only (you can do this via a URL set (for HTTP/HTTPS access) or via domain name set (for any protocols), you can find more information below:

http://technet.microsoft.com/en-us/library/cc441706.aspx Processing domain name sets and URL sets

Since the customer was connecting to https://www.videoondemandwebsite.com , we have added this domain to the rule target. But afterwards the video access was still failing. Then we decided to collect more information on what kind of http activity was taking place on the client side. I asked the customer to install Fiddler on the client to see this activity (you can download the tool at http://www.fiddler2.com)

You’ll find below a sample screen shot taken from Fiddler which was taken when accessing Microsoft’s web site:

As you can see from the above output, even if you see a certain address in IE (www.microsoft.com in this example), the browser might need to connect to other related web sites to load some images, to get a script, etc etc. In the above example, browser also connects to ads1.msn.com or rad.msn.com ...

That was the case in my customer problem, even though the customer was connecting to https://www.videoondemandwebsite.com, the browser was connecting to a few other web sites like *.site1.com and *.site2.com. So we changed the relevant rule to cover these domain names as well and the problem was resolved:

*.videoondemandwebsite.com

*.site1.com

*.site2.com

Hope this helps

Thanks,

Murat

Anatomy of a DoS attack that exploits WebDAV vulnerability in Apache Web server

2011-09-08T08:31:00Z

Hi there,

It has been sometime since I haven’t posted anything at the blog and finally got a chance to do so.

Recently I helped a colleague of mine to investigate a “Windows server connects to unknown destinations” problem. Our customer reported that they were unable to use their internet connections when they start up a certain Windows 2003 server in their network. After some troubleshooting at their side, they concluded that Windows 2003 server was generating excessive UDP activity towards random IP addresses at random times and they were asking for help with finding out the relevant process on the Windows 2003 server side that was generating that traffic.

We asked them to collect a network trace while the problem was visible. As the problem happened very frequently, it didn’t take them long to collect such a network trace. After analyzing the network trace collected, I found out the process that was source of the excessive traffic. Now let’s walk it through together:

a) First of all I tried to identify the excessive UDP traffic. It was like below:

...

303 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 UDP UDP:SrcPort = 2976, DstPort = 10647, Length = 8200 {UDP:48, IPv4:47}

304 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 1480] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 814, Total IP Length = 1500 {IPv4:47}

305 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 2960] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 814, Total IP Length = 1500 {IPv4:47}

306 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 4440] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 814, Total IP Length = 1500 {IPv4:47}

307 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 5920] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 814, Total IP Length = 1500 {IPv4:47}

308 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 7400] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 814, Total IP Length = 820 {IPv4:47}

309 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 UDP UDP:SrcPort = 2976, DstPort = 10647, Length = 8200 {UDP:48, IPv4:47}

310 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 1480] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 815, Total IP Length = 1500 {IPv4:47}

311 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 2960] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 815, Total IP Length = 1500 {IPv4:47}

312 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 4440] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 815, Total IP Length = 1500 {IPv4:47}

313 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 5920] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 815, Total IP Length = 1500 {IPv4:47}

314 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 IPv4 IPv4:[Fragment, Offset = 7400] Src = 20.0.0.1, Dest = 192.168.1.105, Next Protocol = UDP, Packet ID = 815, Total IP Length = 820 {IPv4:47}

315 16:19:48 10.08.2011 0.0000000 33.9062500 20.0.0.1 192.168.1.105 UDP UDP:SrcPort = 2976, DstPort = 10647, Length = 8200 {UDP:48, IPv4:47}

...

There were thousands of such UDP packets without meaningful data being sent to the very same target

NOTE: I deliberately changed the public IP address targeted to 192.168.1.105

b) After that, I tried to track back the starting point and I found the following in the network trace:

302 16:19:48 10.08.2011 21.7031250 33.9062500 httpd.exe 172.16.10.5 20.0.0.1 HTTP HTTP:Request, GET /webdav/shell.php, Query:act=phptools&host=192.168.1.105&time=120&port=3074 {HTTP:46, TCP:45, IPv4:20}

NOTE: I deliberately changed the source public IP address to 172.16.10.5 (from where the attack was initiated)

Note: I was lucky here as Network Monitor easily identified the relevant process. If you cannot see the process easily, you may want to try other methods given at the following post:

http://blogs.technet.com/b/nettracer/archive/2010/08/02/have-you-ever-wanted-to-see-which-windows-process-sends-a-certain-packet-out-to-network.aspx

c) After some research, I found out that this was a vulnerability with Webdav within Apache Web server

http://www.apachefriends.org/f/viewtopic.php?f=5&t=45534 [SOLVED] httpd.exe maxing internet connection...

http://www.opensc.ws/off-topic/11895-webdav-link-crawler-ip-scanner.html

So the attacker was using the customer’s Windows 2003 server as a victim to start DoS (Denial of service) attacks to other hosts...

d) After the customer upgraded the Apache Web server version to the latest one, the issue was resolved J

Long story short, always keep your all software up to date, not just the OS and its services running

Cheers,

Murat

How it works under the hood: A closer look at TCPIP and Winsock ETL tracing on Windows 7 and Windows 2008 R2 with an example

2010-10-06T15:58:00Z

Hi there,

In this blog post, I would like to talk about TCPIP, Winsock ETL tracing a bit with an example to show you how powerful those tracing facilities could be when troubelshooting connectivity problems. Please note that it is to give you an idea about what kind of information could be retrieved from such ETL traces and not to talk about those tracing facilities inside out. But I’m pretty sure you’ll have an idea at the end.

First of all, you need to be running on Windows 7 or Windows 2008 R2 in order to collect the ETL traces I mention here (at least at a detail level mentioned here - also the given netsh command only runs on Windows 7/2008 R2). Let me explain from scratch how I collected those ETL traces:

1) I compiled two sample C# network applications from the following links:

Server application:

(A sample TCPListener class code taken from MSDN http://msdn.microsoft.com/en-us/library/system.net.sockets.tcplistener.aspx)

Client application:

(A sample TCPClient class code taken from MSDN http://msdn.microsoft.com/en-us/library/system.net.sockets.tcpclient.aspx)

=> You can see the complete code from server side below (to make it easier for you while following TCPIP and Winsock activity in the ETL trace below)

///////////////// SERVER CODE //////////////

using System;

using System.IO;

using System.Net;

using System.Net.Sockets;

using System.Text;

class MyTcpListener

{

public static void Main()

{

TcpListener server = null;

try

{

// Set the TcpListener on port 13000.

Int32 port = 13000;

IPAddress localAddr = IPAddress.Parse("192.168.1.212");

// TcpListener server = new TcpListener(port);

server = new TcpListener(localAddr, port);

// Start listening for client requests.

server.Start();

// Buffer for reading data

Byte[] bytes = new Byte[256];

String data = null;

// Enter the listening loop.

while (true)

{

Console.Write("Waiting for a connection... ");

// Perform a blocking call to accept requests.

// You could also user server.AcceptSocket() here.

TcpClient client = server.AcceptTcpClient();

Console.WriteLine("Connected!");

data = null;

// Get a stream object for reading and writing

NetworkStream stream = client.GetStream();

int i;

// Loop to receive all the data sent by the client.

while ((i = stream.Read(bytes, 0, bytes.Length)) != 0)

{

// Translate data bytes to a ASCII string.

data = System.Text.Encoding.ASCII.GetString(bytes, 0, i);

Console.WriteLine("Received: {0}", data);

// Process the data sent by the client.

data = data.ToUpper();

byte[] msg = System.Text.Encoding.ASCII.GetBytes(data);

// Send back a response.

stream.Write(msg, 0, msg.Length);

Console.WriteLine("Sent: {0}", data);

}

// Shutdown and end connection

client.Close();

}

catch (SocketException e)

{

Console.WriteLine("SocketException: {0}", e);

}

finally

{

// Stop listening for new clients.

server.Stop();

}

Console.WriteLine("\nHit enter to continue...");

Console.Read();

}

///////////////// SERVER CODE //////////////

Server code does the following in simple terms:

- It binds to and starts listening on 192.168.1.212:13000 locally via TcpListener()

- Once there’s an incoming connection, it accepts the connection and reads the incoming data stream in 256 byte chunks and converts it to upper case and sends back to the client until a disconnect request is sent by the client (with a socket close at the client side which will be visible as a TCP FIN most of the time at the server side)

2) Then I started ETL tracing with the following command at the server side:

netsh trace start scenario=internetclient provider=Microsoft-Windows-TCPIP capture=yes tracefile=tcpip.etl

Note: capture=yes parameter also starts a network trace which is also collected in ETL format. This is another cool feature of netsh trace command on Windows 7/2008 R2.

Note: You need to run the above command from an elevated command prompt

3) Then I started tcpserver.exe at the server side and then started tcpclient.exe at the client side. Once the tcpclient.exe is started, it connects to server and then sends a 13 bytes message “Test message1” and reads from the socket to get the response from the server and then closes the connection.

4) Then I stopped ETL tracing with the following command at the server side:

netsh trace stop

5) As a result of this action, an ETL file named tcpip.etl was created and then I opened it with Network Monitor 3.4 since it supports decoding ETL files. You can see an example screenshot below:

6) Now let’s focus on the session over which communication took place. You can find the relevant session by browsing the conversations at the left pane. In this scenario the right conversation was 12

Note: I used the following color coding in order to better distinguish TCPIP driver, AFD driver activities and real network packets:

Winsock activity

TCPIP driver activity

Network packets

Note: You can also see below the network packets that belong to the given session for your convenience: (even though individual packets will be examined)

196 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=......S., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959134, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192

199 Idle (0) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590241, Ack=260959135, Win=8192 ( Negotiated scale factor 0x8 ) = 8192

200 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959135, Ack=2428590242, Win=513

213 tcpserver.exe (2704) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...AP..., SrcPort=55908, DstPort=13000, PayloadLen=13, Seq=260959135 - 260959148, Ack=2428590242, Win=513

223 tcpserver.exe (2704) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...AP..., SrcPort=13000, DstPort=55908, PayloadLen=13, Seq=2428590242 - 2428590255, Ack=260959148, Win=513 (scale factor 0x0) = 513

227 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...F, SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959148, Ack=2428590255, Win=513

235 Idle (0) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A...., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

239 tcpserver.exe (2704) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A...F, SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

245 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959149, Ack=2428590256, Win=513

a) The following WinsockAFD/TCPIP activity is a result of the following code fragment at server:

...

// Set the TcpListener on port 13000.

Int32 port = 13000;

IPAddress localAddr = IPAddress.Parse("192.168.1.212");

// TcpListener server = new TcpListener(port);

server = new TcpListener(localAddr, port);

Calling TcpListener constructor triggers a socket creation and local bind activity at the server side behind the scenes. As can be seen from the following converted ETL lines, the server process (tcpserver.exe) is binding to 192.168.1.212:13000

50 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket: 0 (0x0): Process 0x893F92B0 (0x00000A90), Endpoint 0x8A28E2D8, Family 2 (0x2), Type SOCK_STREAM, Protocol 6 (0x6), Seq 1006 (0x3EE), Status Success

51 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV4 PID=2704 (0xA90)) created.

52 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x89304008 (Family=IPV4, PID=2704 (0xA90)) created with status = Success.

53 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket: 1 (0x1): Process 0x893F92B0 (0x00000A90), Endpoint 0x8A28E2D8, Family 0 (0x0), Type Unknown value: 0, Protocol 0 (0x0), Seq 1013 (0x3F5), Status Success

54 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:bind: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.212:13000, Seq 7010 (0x1B62), Status Success

55 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x89304008 acquired port number 13000 (0x32C8).

56 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.212:13000) bound.

57 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:bind: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.212:13000, Seq 7022 (0x1B6E), Status Success

b) Then the server makes the following call to start listening on the socket and accept any incoming connection requests:

...

// Start listening for client requests.

server.Start();

// Buffer for reading data

Byte[] bytes = new Byte[256];

String data = null;

// Enter the listening loop.

while (true)

{

Console.Write("Waiting for a connection... ");

// Perform a blocking call to accept requests.

// You could also user server.AcceptSocket() here.

TcpClient client = server.AcceptTcpClient();

...

58 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:Listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Backlog 200 (0xC8), Seq 13006 (0x32CE), Status Success

59 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x8A213398 replaced base endpoint 0x89304008 and acquired reference to port number 13000 (0x32C8).

60 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: listener 0x8A213398 (sockaddr=192.168.1.212:13000) activated.

61 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:Listen: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Backlog 200 (0xC8), Seq 13012 (0x32D4), Status Success

62 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.212:13000) closed.

63 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6216 (0x1848), Status Success

c) After some time, a remote client connects to server at TCP port 13000. This can be seen from the TCP SYN packet received from WIN7CLIENT1-2K8 (192.168.1.200)

196 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=......S., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959134, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192

d) TCPIP driver immediately responds to TCP SYN with a TCP SYN ACK and it also moves to SynRcvdState from ListenState:

197 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from ListenState to SynRcvdState, SndNxt = 0 (0x0).

198 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 1 (0x1) and Sequence number = 2428590241 (0x90C158A1).

199 Idle (0) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A..S., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590241, Ack=260959135, Win=8192 ( Negotiated scale factor 0x8 ) = 8192

200 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959135, Ack=2428590242, Win=513

e) After receiving a TCP ACK from the client, the endpoint moves to EstablishedState which is the state where both parties could start exchanging data:

201 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 0 (0x0). ThSeq = 260959135 (0xF8DEB9F).

202 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from SynRcvdState to EstablishedState, SndNxt = 2428590242 (0x90C158A2).

f) Now Winsock driver indicates a connection request to the application layer (tcpserver) and then the connection is accepted by the server process:

203 Idle (0) 192.168.1.200 Wscore_MicrosoftWindowsWinsockAFD:Connect indication: 3 (0x3): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.200:55908, Backlog Count 0 (0x0), Seq 6501 (0x1965), Status Success

204 Idle (0) Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6220 (0x184C), Status Success

205 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: listener (local=192.168.1.212:13000 remote=192.168.1.200:55908) accept completed. TCB = 0x8921DD28. PID = 2704 (0xA90).

206 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket: 0 (0x0): Process 0x893F92B0 (0x00000A90), Endpoint 0x892FB6D8, Family 2 (0x2), Type SOCK_STREAM, Protocol 6 (0x6), Seq 1006 (0x3EE), Status Success

207 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV4 PID=2704 (0xA90)) created.

208 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x88BF7B08 (Family=IPV4, PID=2704 (0xA90)) created with status = Success.

209 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket: 1 (0x1): Process 0x893F92B0 (0x00000A90), Endpoint 0x892FB6D8, Family 0 (0x0), Type Unknown value: 0, Protocol 0 (0x0), Seq 1013 (0x3F5), Status Success

210 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:accept: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.200:55908, Accept Endpoint 0x892FB6D8, Current Backlog 0 (0x0), Seq 6010 (0x177A), Status Success

211 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0.0.0.0:0) closed.

212 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:accept: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6011 (0x177B), Status Success

g) Remote client sends 13 bytes of data to the Server:

213 tcpserver.exe (2704) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...AP..., SrcPort=55908, DstPort=13000, PayloadLen=13, Seq=260959135 - 260959148, Ack=2428590242, Win=513

54 65 73 74 20 6D 65 73 73 61 67 65 31 Test message1

h) And this is reflected with a Data indication to the application:

214 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:Data indication: 3 (0x3): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer 0x89C5BD88, Length 13 (0xD), Seq 9000 (0x2328)

215 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 delivery 0x8921DE20 indicated 0x0000000D bytes accepted 0x0000000D bytes, status = Success. RcvNxt = 260959135 (0xF8DEB9F).

216 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 13 (0xD). ThSeq = 260959135 (0xF8DEB9F).

i) Now the client posts a Recv() with a buffer size of 256 bytes which is a result of the following server code fragment and it receives 13 bytes in return which was just received from the remote client:

...

// Buffer for reading data

Byte[] bytes = new Byte[256];

String data = null;

...

// Loop to receive all the data sent by the client.

while ((i = stream.Read(bytes, 0, bytes.Length)) != 0)

{

...

217 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:recv: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x0197F300, Length 256 (0x100), Seq 4115 (0x1013), Status Success

218 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:recv: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x0197F300, Length 13 (0xD), Seq 4116 (0x1014), Status Success

j) After receiving the data, server code converts it to upper case and send back to the client with the following code which is again 13 bytes in length:

...

data = data.ToUpper();

byte[] msg = System.Text.Encoding.ASCII.GetBytes(data);

// Send back a response.

stream.Write(msg, 0, msg.Length);

Console.WriteLine("Sent: {0}", data);

...

219 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:send: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3047 (0xBE7), Status Success

220 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:send: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3056 (0xBF0), Status Success

221 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 send posted posted 13 (0xD) bytes at 2428590242 (0x90C158A2).

222 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 13 (0xD) and Sequence number = 2428590242 (0x90C158A2).

224 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:send: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3051 (0xBEB), Status Success

k) Another Recv() with an 256 bytes buffer is posted by the application: (since the server is still in the while loop)

225 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:recv: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x892810E8, Length 256 (0x100), Seq 4107 (0x100B), Status Success

226 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28, delivery 0x8921DE20, Request 0x89E65020 posted for 0x00000100 bytes, flags = 0 (0x0). RcvNxt = 260959148 (0xF8DEBAC).

l) The remote client sends a TCP FIN segment to the server and this is indicated up to the application and also the endpoint moves to CloseWaitState:

227 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...F, SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959148, Ack=2428590255, Win=513

228 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 1 (0x1). ThSeq = 260959148 (0xF8DEBAC).

229 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Cumulative ACK updated cwnd = 2920 (0xB68).

230 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from EstablishedState to CloseWaitState, SndNxt = 2428590255 (0x90C158AF).

m) Server process determines that the remote client wants to close the connection by getting 0 bytes out of recv(): (which was posted by stream.Read(bytes, 0, bytes.Length) call indirectly)

231 Idle (0) Wscore_MicrosoftWindowsWinsockAFD:recv: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x892810E8, Length 0 (0x0), Seq 4123 (0x101B), Status Success

232 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 delivery 0x8921DE20 delivering FIN. RcvNxt = 260959149 (0xF8DEBAD).

n) Server process also issues a disconnect by calling the following:

...

// Shutdown and end connection

client.Close();

...

233 Idle (0) Wscore_MicrosoftWindowsWinsockAFD:disconnect indicated: 3 (0x3): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 12001 (0x2EE1)

234 Idle (0) Wscore_MicrosoftWindowsWinsockAFD:send: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3024 (0xBD0), Status Success

235 Idle (0) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A...., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

236 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection disconnect issued, length=0x00000000.

237 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from CloseWaitState to LastAckState, SndNxt = 2428590255 (0x90C158AF).

238 tcpserver.exe (2704) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 1 (0x1) and Sequence number = 2428590255 (0x90C158AF).

239 tcpserver.exe (2704) WIN7CLIENT1-2K8 W2K8DC1 TCP TCP: [Bad CheckSum]Flags=...A...F, SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

o) Finally the server does the socket cleanup:

240 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2002 (0x7D2), Status Success

241 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2003 (0x7D3), Status Success

242 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:closesocket: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2000 (0x7D0), Status Success

243 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:closesocket: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2001 (0x7D1), Status Success

244 tcpserver.exe (2704) Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6216 (0x1848), Status Success

p) And after receiving an ACK to the FIN sent by the server, the session moves to ClosedState:

245 Idle (0) W2K8DC1 WIN7CLIENT1-2K8 TCP TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959149, Ack=2428590256, Win=513

246 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 0 (0x0). ThSeq = 260959149 (0xF8DEBAD).

247 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Cumulative ACK updated cwnd = 2933 (0xB75).

248 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from LastAckState to ClosedState, SndNxt = 2428590256 (0x90C158B0).

249 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) disconnect completed.

250 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) close issued.

251 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) shutdown initiated (0xC0000241 - STATUS_CONNECTION_ABORTED). PID = 2704 (0xA90).

252 Idle (0) TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from ClosedState to ClosedState, SndNxt = 2428590256 (0x90C158B0).

Hope this helps

Thanks,

Murat